removed access-log build option and log parser. added incoming_request_alert. This feature can now be implemented by clients

This commit is contained in:
Arvid Norberg 2015-05-09 03:04:08 +00:00
parent ddfef97696
commit a83dcbaaf0
13 changed files with 49 additions and 428 deletions

View File

@ -441,9 +441,6 @@ feature invariant-checks : on off full : composite propagated link-incompatible
feature.compose <invariant-checks>off : <define>TORRENT_DISABLE_INVARIANT_CHECKS ;
feature.compose <invariant-checks>full : <define>TORRENT_EXPENSIVE_INVARIANT_CHECKS ;
feature request-log : off on : composite propagated link-incompatible ;
feature.compose <request-log>on : <define>TORRENT_REQUEST_LOGGING ;
feature disk-stats : off on : composite propagated link-incompatible ;
feature.compose <disk-stats>on : <define>TORRENT_DISK_STATS ;
@ -508,7 +505,7 @@ variant test_release
;
variant test_debug : debug
: <crypto>openssl <logging>on <disk-stats>on
<dht>logging <request-log>on <allocator>debug <debug-iterators>on
<dht>logging <allocator>debug <debug-iterators>on
<invariant-checks>full <boost-link>shared
<export-extra>on <debug-iterators>on <boost>source <threading>multi
;

View File

@ -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``. |

View File

@ -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

View File

@ -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<dht_routing_bucket> 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 };
}

View File

@ -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<boost::shared_ptr<tracker_logger> > m_tracker_loggers;
#endif
#ifdef TORRENT_REQUEST_LOGGING
FILE* m_request_logger;
#endif
private:

View File

@ -341,10 +341,6 @@ namespace libtorrent { namespace aux
virtual void prioritize_dht(boost::weak_ptr<torrent> 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;

View File

@ -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

View File

@ -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<incoming_request_alert>())
{
t->alerts().emplace_alert<incoming_request_alert>(r, t->get_handle()
, m_remote, m_peer_id);
}
m_last_incoming_request = aux::time_now();
fill_send_buffer();
}

View File

@ -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)

View File

@ -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

View File

@ -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 : <include>../ed25519/src ;
explicit parse_hash_fails ;

View File

@ -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

View File

@ -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 <cstring>
#include <boost/bind.hpp>
#include <stdlib.h>
#include <map>
#include <vector>
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<boost::uint64_t, boost::uint64_t> 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<boost::uint64_t, object_entry> torrent_map;
std::map<boost::uint64_t, object_entry> piece_map;
std::map<boost::uint64_t, average_time> piece_frequency_map;
std::map<boost::uint32_t, object_entry> 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<std::pair<object_entry, boost::uint64_t> > histogram;
for (std::map<boost::uint64_t, object_entry>::iterator i = torrent_map.begin()
, end(torrent_map.end()); i != end; ++i)
{
histogram.push_back(std::pair<object_entry, boost::uint64_t>(i->second, i->first));
}
std::sort(histogram.begin(), histogram.end());
int count = 0;
for (std::vector<std::pair<object_entry, boost::uint64_t> >::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<boost::uint32_t, object_entry>::iterator i = peer_map.begin()
, end(peer_map.end()); i != end; ++i)
{
histogram.push_back(std::pair<object_entry, boost::uint64_t>(i->second, i->first));
}
std::sort(histogram.begin(), histogram.end());
count = 0;
for (std::vector<std::pair<object_entry, boost::uint64_t> >::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<boost::uint64_t, object_entry>::iterator i = piece_map.begin()
, end(piece_map.end()); i != end; ++i)
{
histogram.push_back(std::pair<object_entry, boost::uint64_t>(i->second, i->first));
}
std::sort(histogram.begin(), histogram.end());
count = 0;
for (std::vector<std::pair<object_entry, boost::uint64_t> >::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<std::pair<object_entry, boost::uint64_t> >::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;
}