From a83dcbaaf07cef6f25c322a31122eb7317333e1f Mon Sep 17 00:00:00 2001 From: Arvid Norberg Date: Sat, 9 May 2015 03:04:08 +0000 Subject: [PATCH] removed access-log build option and log parser. added incoming_request_alert. This feature can now be implemented by clients --- Jamfile | 5 +- docs/building.rst | 11 - include/libtorrent/alert.hpp | 3 + include/libtorrent/alert_types.hpp | 25 +- include/libtorrent/aux_/session_impl.hpp | 9 - include/libtorrent/aux_/session_interface.hpp | 4 - src/alert.cpp | 15 + src/peer_connection.cpp | 42 +-- src/session_impl.cpp | 21 -- src/upnp.cpp | 2 +- tools/Jamfile | 1 - tools/Makefile.am | 2 - tools/parse_request_log.cpp | 337 ------------------ 13 files changed, 49 insertions(+), 428 deletions(-) delete mode 100644 tools/parse_request_log.cpp diff --git a/Jamfile b/Jamfile index 790ccbe22..06b9f937e 100755 --- a/Jamfile +++ b/Jamfile @@ -441,9 +441,6 @@ feature invariant-checks : on off full : composite propagated link-incompatible feature.compose off : TORRENT_DISABLE_INVARIANT_CHECKS ; feature.compose full : TORRENT_EXPENSIVE_INVARIANT_CHECKS ; -feature request-log : off on : composite propagated link-incompatible ; -feature.compose on : TORRENT_REQUEST_LOGGING ; - feature disk-stats : off on : composite propagated link-incompatible ; feature.compose on : TORRENT_DISK_STATS ; @@ -508,7 +505,7 @@ variant test_release ; variant test_debug : debug : openssl on on - logging on debug on + logging debug on full shared on on source multi ; diff --git a/docs/building.rst b/docs/building.rst index 6b93df1a6..27c881d72 100644 --- a/docs/building.rst +++ b/docs/building.rst @@ -273,10 +273,6 @@ Build features: | | filename. | | | * ``system`` use the libc assert macro | +--------------------------+----------------------------------------------------+ -| ``upnp-logging`` | * ``off`` - default. Does not log UPnP traffic. | -| | * ``on`` - creates "upnp.log" with the messages | -| | sent to and received from UPnP devices. | -+--------------------------+----------------------------------------------------+ | ``encryption`` | * ``on`` - encrypted bittorrent connections | | | enabled. (Message Stream encryption). | | | * ``off`` - turns off support for encrypted | @@ -367,8 +363,6 @@ Build features: | | ordered by the number of them. | +--------------------------+----------------------------------------------------+ -.. _MaxMind: http://www.maxmind.com/app/api - The ``variant`` feature is *implicit*, which means you don't need to specify the name of the feature, just the value. @@ -540,11 +534,6 @@ defines you can use to control the build. | | checks in the storage, including logging of | | | piece sorting. | +----------------------------------------+-------------------------------------------------+ -| ``TORRENT_UPNP_LOGGING`` | Generates a "upnp.log" file with the UPnP | -| | traffic. This is very useful when debugging | -| | support for various UPnP routers. | -| | support for various UPnP routers. | -+----------------------------------------+-------------------------------------------------+ | ``TORRENT_DISK_STATS`` | This will create a log of all disk activity | | | which later can parsed and graphed using | | | ``parse_disk_log.py``. | diff --git a/include/libtorrent/alert.hpp b/include/libtorrent/alert.hpp index cf166e65c..811787410 100644 --- a/include/libtorrent/alert.hpp +++ b/include/libtorrent/alert.hpp @@ -186,6 +186,9 @@ namespace libtorrent { // peer_log_alert and low-level peer events and messages. peer_log_notification = 0x8000, + // enables the incoming_request_alert. + incoming_request_notification = 0x10000, + // The full bitmask, representing all available categories. // // since the enum is signed, make sure this isn't diff --git a/include/libtorrent/alert_types.hpp b/include/libtorrent/alert_types.hpp index 744c45d85..369278c48 100644 --- a/include/libtorrent/alert_types.hpp +++ b/include/libtorrent/alert_types.hpp @@ -98,11 +98,11 @@ namespace libtorrent // The peer alert is a base class for alerts that refer to a specific peer. It includes all // the information to identify the peer. i.e. ``ip`` and ``peer-id``. - struct TORRENT_EXPORT peer_alert: torrent_alert + struct TORRENT_EXPORT peer_alert : torrent_alert { // internal peer_alert(aux::stack_allocator& alloc, torrent_handle const& h, - tcp::endpoint const& i , peer_id const& pi); + tcp::endpoint const& i, peer_id const& pi); static const int alert_type = 1; static const int static_category = alert::peer_notification; @@ -2295,13 +2295,32 @@ namespace libtorrent std::vector routing_table; }; + // posted every time an incoming request from a peer is accepted and queued + // up for being serviced. This alert is only posted if + // the alert::incoming_request_notification flag is enabled in the alert + // mask. + struct TORRENT_EXPORT incoming_request_alert : peer_alert + { + // internal + incoming_request_alert(aux::stack_allocator& alloc + , peer_request r, torrent_handle h + , tcp::endpoint const& ep, peer_id const& peer_id); + + static const int static_category = alert::incoming_request_notification; + TORRENT_DEFINE_ALERT(incoming_request_alert, 84) + + virtual std::string message() const; + + // the request this peer sent to us + peer_request req; + }; #undef TORRENT_DEFINE_ALERT_IMPL #undef TORRENT_DEFINE_ALERT #undef TORRENT_DEFINE_ALERT_PRIO #undef TORRENT_CLONE - enum { num_alert_types = 84 }; + enum { num_alert_types = 85 }; } diff --git a/include/libtorrent/aux_/session_impl.hpp b/include/libtorrent/aux_/session_impl.hpp index 9038df8b5..87bc7d4ad 100644 --- a/include/libtorrent/aux_/session_impl.hpp +++ b/include/libtorrent/aux_/session_impl.hpp @@ -1106,12 +1106,6 @@ namespace libtorrent void check_invariant() const; #endif -#ifdef TORRENT_REQUEST_LOGGING - // used to log all requests from peers - FILE* m_request_log; - FILE* get_request_log() { return m_request_log; } -#endif - counters& stats_counters() { return m_stats_counters; } void received_buffer(int size); @@ -1144,9 +1138,6 @@ namespace libtorrent // whe shutting down process std::list > m_tracker_loggers; #endif -#ifdef TORRENT_REQUEST_LOGGING - FILE* m_request_logger; -#endif private: diff --git a/include/libtorrent/aux_/session_interface.hpp b/include/libtorrent/aux_/session_interface.hpp index c37be35d9..fc70c7029 100644 --- a/include/libtorrent/aux_/session_interface.hpp +++ b/include/libtorrent/aux_/session_interface.hpp @@ -341,10 +341,6 @@ namespace libtorrent { namespace aux virtual void prioritize_dht(boost::weak_ptr t) = 0; #endif -#ifdef TORRENT_REQUEST_LOGGING - virtual FILE* get_request_log() = 0; -#endif - virtual counters& stats_counters() = 0; virtual void received_buffer(int size) = 0; virtual void sent_buffer(int size) = 0; diff --git a/src/alert.cpp b/src/alert.cpp index c0524e0cb..52a4c56d6 100644 --- a/src/alert.cpp +++ b/src/alert.cpp @@ -1694,6 +1694,21 @@ namespace libtorrent { + (operation?operation:"") + " (" + filename() + ") error: " + convert_from_native(error.message()); } + + incoming_request_alert::incoming_request_alert(aux::stack_allocator& alloc + , peer_request r, torrent_handle h + , tcp::endpoint const& ep, peer_id const& peer_id) + : peer_alert(alloc, h, ep, peer_id) + , req(r) + {} + + std::string incoming_request_alert::message() const + { + char msg[1024]; + snprintf(msg, sizeof(msg), "%s: incoming request [ piece: %d start: %d length: %d ]" + , peer_alert::message().c_str(), req.piece, req.start, req.length); + return msg; + } } // namespace libtorrent diff --git a/src/peer_connection.cpp b/src/peer_connection.cpp index 00c7e913e..4408745e3 100644 --- a/src/peer_connection.cpp +++ b/src/peer_connection.cpp @@ -106,36 +106,6 @@ namespace libtorrent } -#if defined TORRENT_REQUEST_LOGGING - void write_request_log(FILE* f, sha1_hash const& ih - , peer_connection* p, peer_request const& r) - { - // the event format in the log is: - // uint64_t timestamp (microseconds) - // uint64_t info-hash prefix - // uint32_t peer identifier - // uint32_t piece - // uint32_t start offset - // uint32_t length - char event[32]; - char* ptr = event; - detail::write_uint64(clock_type::now().time_since_epoch().count(), ptr); - memcpy(ptr, &ih[0], 8); - ptr += 8; - detail::write_uint32(uintptr_t(p) & 0xffffffff, ptr); - detail::write_uint32(r.piece, ptr); - detail::write_uint32(r.start, ptr); - detail::write_uint32(r.length, ptr); - - int ret = fwrite(event, 1, sizeof(event), f); - if (ret != sizeof(event)) - { - fprintf(stderr, "ERROR writing to request log: (%d) %s\n" - , errno, strerror(errno)); - } - } -#endif - #if TORRENT_USE_ASSERTS bool peer_connection::is_single_thread() const { @@ -2428,11 +2398,13 @@ namespace libtorrent m_counters.inc_stats_counter(counters::num_peers_up_requests); m_requests.push_back(r); -#ifdef TORRENT_REQUEST_LOGGING - FILE* log = m_ses.get_request_log(); - if (log) - write_request_log(log, t->info_hash(), this, r); -#endif + + if (t->alerts().should_post()) + { + t->alerts().emplace_alert(r, t->get_handle() + , m_remote, m_peer_id); + } + m_last_incoming_request = aux::time_now(); fill_send_buffer(); } diff --git a/src/session_impl.cpp b/src/session_impl.cpp index b85ffedd2..77b2391ce 100644 --- a/src/session_impl.cpp +++ b/src/session_impl.cpp @@ -442,23 +442,6 @@ namespace aux { m_ssl_udp_socket.subscribe(this); #endif - // TODO: 3 remove REQUESST_LOGGING build configuration. Make sure the - // same information can be logged via alerts -#ifdef TORRENT_REQUEST_LOGGING - char log_filename[200]; -#ifdef TORRENT_WINDOWS - const int pid = GetCurrentProcessId(); -#else - const int pid = getpid(); -#endif - snprintf(log_filename, sizeof(log_filename), "requests-%d.log", pid); - m_request_log = fopen(log_filename, "w+"); - if (m_request_log == 0) - { - fprintf(stderr, "failed to open request log file: (%d) %s\n", errno, strerror(errno)); - } -#endif - error_code ec; m_listen_interface = tcp::endpoint(address_v4::any(), 0); TORRENT_ASSERT_VAL(!ec, ec); @@ -5658,10 +5641,6 @@ retry: TORRENT_ASSERT(m_torrents.empty()); TORRENT_ASSERT(m_connections.empty()); -#ifdef TORRENT_REQUEST_LOGGING - if (m_request_log) fclose(m_request_log); -#endif - #if defined TORRENT_ASIO_DEBUGGING FILE* f = fopen("wakeups.log", "w+"); if (f != NULL) diff --git a/src/upnp.cpp b/src/upnp.cpp index 7f41dc91d..06a3bb155 100644 --- a/src/upnp.cpp +++ b/src/upnp.cpp @@ -69,7 +69,7 @@ namespace upnp_errors static error_code ec; -// TODO: listen_interface is not used. It's meant to bind the broadcast socket +// TODO: 3 listen_interface is not used. It's meant to bind the broadcast socket upnp::upnp(io_service& ios , address const& listen_interface, std::string const& user_agent , portmap_callback_t const& cb, log_callback_t const& lcb diff --git a/tools/Jamfile b/tools/Jamfile index 99232d03e..441822143 100644 --- a/tools/Jamfile +++ b/tools/Jamfile @@ -36,7 +36,6 @@ project tools exe fuzz_torrent : fuzz_torrent.cpp ; exe parse_hash_fails : parse_hash_fails.cpp ; exe parse_access_log : parse_access_log.cpp ; -exe parse_request_log : parse_request_log.cpp ; exe dht : dht_put.cpp : ../ed25519/src ; explicit parse_hash_fails ; diff --git a/tools/Makefile.am b/tools/Makefile.am index eea60386a..fedaca5c6 100644 --- a/tools/Makefile.am +++ b/tools/Makefile.am @@ -1,5 +1,4 @@ tool_programs = \ - parse_request_log \ fuzz_torrent if ENABLE_EXAMPLES @@ -26,7 +25,6 @@ EXTRA_DIST = Jamfile \ run_regression_tests.py\ run_tests.py -parse_request_log_SOURCES = parse_request_log.cpp fuzz_torrent_SOURCES = fuzz_torrent.cpp LDADD = $(top_builddir)/src/libtorrent-rasterbar.la diff --git a/tools/parse_request_log.cpp b/tools/parse_request_log.cpp deleted file mode 100644 index c719f652e..000000000 --- a/tools/parse_request_log.cpp +++ /dev/null @@ -1,337 +0,0 @@ -/* - -Copyright (c) 2012, Arvid Norberg -All rights reserved. - -Redistribution and use in source and binary forms, with or without -modification, are permitted provided that the following conditions -are met: - - * Redistributions of source code must retain the above copyright - notice, this list of conditions and the following disclaimer. - * Redistributions in binary form must reproduce the above copyright - notice, this list of conditions and the following disclaimer in - the documentation and/or other materials provided with the distribution. - * Neither the name of the author nor the names of its - contributors may be used to endorse or promote products derived - from this software without specific prior written permission. - -THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS "AS IS" -AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE -IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE -ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT OWNER OR CONTRIBUTORS BE -LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR -CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF -SUBSTITUTE GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS -INTERRUPTION) HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN -CONTRACT, STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) -ARISING IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE -POSSIBILITY OF SUCH DAMAGE. - -*/ - -#include "libtorrent/file.hpp" -#include "libtorrent/io.hpp" -#include -#include -#include -#include -#include - -using namespace libtorrent; -using namespace libtorrent::detail; // for write_* and read_* - -void print_usage() -{ - fprintf(stderr, "usage: parse_request_log log-file\n"); - exit(1); -} - -// the event format in the log is: -// uint64_t timestamp (microseconds) -// uint64_t info-hash prefix -// uint32_t peer identifier -// uint32_t piece -// uint32_t start offset -// uint32_t length - -struct request -{ - boost::uint64_t timestamp; - boost::uint64_t infohash; - boost::uint32_t peer; - boost::uint32_t piece; - boost::uint32_t start; - boost::uint32_t length; -}; - -struct object_entry -{ - int hits; - int cache_hits; - bool operator<(object_entry const& rhs) const - { - return hits < rhs.hits; - } -}; - - - -struct average_time -{ - average_time() : first_request(0), num_requests(0), last_peer(0) {} - - void sample(boost::uint32_t peer, boost::uint64_t timestamp) - { -// if (peer == last_peer) return; -// last_peer = peer; - ++num_requests; - if (first_request == 0) - { - first_request = timestamp; - last_request = timestamp; - } - else - { - assert(timestamp >= last_request); - last_request = timestamp; - } - } - - float request_rate() const - { - if (num_requests <= 8) return 0.f; - return float(num_requests) / float(last_request - first_request) * 1000000.f; - } - boost::uint64_t first_request; - boost::uint64_t last_request; - int num_requests; - boost::uint32_t last_peer; -}; - -struct cache -{ - virtual bool incoming_request(request const& r) = 0; - virtual ~cache() {} -}; - -struct noop_cache : cache -{ - virtual bool incoming_request(request const& r) { return false; } -}; - -struct lru_cache : cache -{ - lru_cache(int size) : m_size(size) {} - virtual bool incoming_request(request const& r) - { - boost::uint64_t piece = (r.infohash & 0xffffffff00000000LL) | r.piece; - cache_t::iterator i = m_cache.find(piece); - if (i != m_cache.end()) - { - i->second = r.timestamp; - return true; - } - - // cache miss, insert this piece - if (m_cache.size() == m_size) - { - // need to evict the least recently used. This is - // a stupid expensive implementation (but simple) - - i = std::min_element(m_cache.begin(), m_cache.end() - , boost::bind(&cache_t::value_type::second, _1) - < boost::bind(&cache_t::value_type::second, _2)); - - m_cache.erase(i); - } - m_cache[piece] = r.timestamp; - return false; - } - int m_size; - // maps piece -> timestamp - typedef std::map cache_t; - cache_t m_cache; -}; - - -int main(int argc, char* argv[]) -{ - if (argc != 2 && argc != 4) print_usage(); - - cache* disk_cache = 0; - - if (argc == 4) - { - int size = atoi(argv[2]); - if (strcmp(argv[1], "lru") == 0) - { - disk_cache = new lru_cache(size); - } - - argv += 2; - } - - if (disk_cache == 0) - { - disk_cache = new noop_cache; - } - - FILE* log_file = fopen(argv[1], "r"); - if (log_file == 0) - { - fprintf(stderr, "failed to open logfile: %s\n%d: %s\n" - , argv[1], errno, strerror(errno)); - return 1; - } - - FILE* expand_file = fopen("expanded_requests.log", "w+"); - std::map torrent_map; - std::map piece_map; - std::map piece_frequency_map; - std::map peer_map; - - boost::uint64_t first_timestamp = 0; - - for (;;) - { - char entry[sizeof(request)]; - char* ptr = entry; - int ret = fread(&entry, 1, sizeof(entry), log_file); - if (ret != sizeof(entry)) break; - - request r; - r.timestamp = read_uint64(ptr); - r.infohash = read_uint64(ptr); - r.peer = read_uint32(ptr); - r.piece = read_uint32(ptr); - r.start = read_uint32(ptr); - r.length = read_uint32(ptr); - - if (first_timestamp == 0) first_timestamp = r.timestamp; - - fprintf(expand_file, "%" PRIu64 "\t%" PRIu64 "\t%" PRIu32 "\t%" PRIu32 "\t%" PRIu32 "\t%" PRIu32 "\n" - , r.timestamp, r.infohash, r.peer, r.piece, r.start, r.length); - - bool hit = disk_cache->incoming_request(r); - - boost::uint64_t piece = (r.infohash & 0xffffffff00000000LL) | r.piece; - torrent_map[r.infohash].hits += 1; - peer_map[r.peer].hits += 1; - piece_map[piece].hits += 1; - piece_frequency_map[piece].sample(r.peer, r.timestamp); - if (hit) - { - torrent_map[r.infohash].cache_hits += 1; - peer_map[r.peer].cache_hits += 1; - piece_map[piece].cache_hits += 1; - } - } - - fclose(expand_file); - - // === torrents === - FILE* file = fopen("torrent_dist.log", "w+"); - std::vector > histogram; - for (std::map::iterator i = torrent_map.begin() - , end(torrent_map.end()); i != end; ++i) - { - histogram.push_back(std::pair(i->second, i->first)); - } - std::sort(histogram.begin(), histogram.end()); - - int count = 0; - for (std::vector >::iterator i = histogram.begin() - , end(histogram.end()); i != end; ++i, ++count) - { - fprintf(file, "%d\t%d\t%d\n", count, i->first.hits, i->first.cache_hits); - } - fclose(file); - - // === peers === - file = fopen("peer_dist.log", "w+"); - histogram.clear(); - for (std::map::iterator i = peer_map.begin() - , end(peer_map.end()); i != end; ++i) - { - histogram.push_back(std::pair(i->second, i->first)); - } - std::sort(histogram.begin(), histogram.end()); - - count = 0; - for (std::vector >::iterator i = histogram.begin() - , end(histogram.end()); i != end; ++i, ++count) - { - fprintf(file, "%d\t%d\t%d\n", count, i->first.hits, i->first.cache_hits); - } - fclose(file); - - // === pieces === - file = fopen("piece_dist.log", "w+"); - histogram.clear(); - for (std::map::iterator i = piece_map.begin() - , end(piece_map.end()); i != end; ++i) - { - histogram.push_back(std::pair(i->second, i->first)); - } - std::sort(histogram.begin(), histogram.end()); - - count = 0; - for (std::vector >::iterator i = histogram.begin() - , end(histogram.end()); i != end; ++i, ++count) - { - fprintf(file, "%d\t%d\t%d\n", count, i->first.hits, i->first.cache_hits); - } - fclose(file); - - // === piece frequency === - file = fopen("piece_frequency_dist.log", "w+"); - // just update the histogram to get the piece mapping the same - - count = 0; - for (std::vector >::iterator i = histogram.begin() - , end(histogram.end()); i != end; ++i, ++count) - { - fprintf(file, "%d\t%f\n", count, piece_frequency_map[i->second].request_rate()); - } - fclose(file); - - FILE* gnuplot = fopen("requests.gnuplot", "w+"); - - char const* gnuplot_file = - "set term png size 1400,1024\n" - "set output \"requests-torrent-histogram.png\"\n" - "set xlabel \"torrent\"\n" - "set ylabel \"number of requests\"\n" - "plot \"torrent_dist.log\" using 1:2 title \"torrent request\" with boxes, " - "\"torrent_dist.log\" using 1:3 title \"torrent cache hits\" with boxes\n" - - "set output \"requests-peer-histogram.png\"\n" - "set xlabel \"peer\"\n" - "set ylabel \"number of requests\"\n" - "plot \"peer_dist.log\" using 1:2 title \"peer request\" with boxes, " - "\"peer_dist.log\" using 1:3 title \"peer cache hits\" with boxes\n" - - "set output \"requests-piece-histogram.png\"\n" - "set xlabel \"piece\"\n" - "set ylabel \"number of requests\"\n" - "plot \"piece_dist.log\" using 1:2 title \"piece requests\" with boxes, " - "\"piece_dist.log\" using 1:3 title \"piece cache hits\" with boxes\n" - - "set output \"requests-piece-frequency-histogram.png\"\n" - "set xlabel \"piece\"\n" - "set ylabel \"average requests per second\"\n" - "set yrange [0: 0.02]\n" - "plot \"piece_frequency_dist.log\" using 1:2 title \"piece request frequency\" with boxes\n" - ; - - - fwrite(gnuplot_file, strlen(gnuplot_file), 1, gnuplot); - fclose(gnuplot); - - system("gnuplot requests.gnuplot"); - - return 0; -} - -