commit 8c3ec7d7253545e94da1ee64598b5bfe5ffb92c5 Author: Zack Weinberg zackw@cmu.edu Date: Wed Jun 20 17:10:24 2012 -0700

Add an abbreviated packet tracing mode. --- src/protocol/chop.cc | 44 +++++++++++++++++++++++++++++++++++++++++++- src/util.cc | 29 ++++++++++++++++++----------- src/util.h | 4 ++++ 3 files changed, 65 insertions(+), 12 deletions(-)

diff --git a/src/protocol/chop.cc b/src/protocol/chop.cc index cde40b2..c865c9b 100644 --- a/src/protocol/chop.cc +++ b/src/protocol/chop.cc @@ -387,6 +387,7 @@ struct chop_config_t : config_t vector<struct evutil_addrinfo *> down_addresses; vector<steg_config_t *> steg_targets; chop_circuit_table circuits; + bool trace_packets;

CONFIG_DECLARE_METHODS(chop); }; @@ -396,6 +397,7 @@ struct chop_config_t : config_t chop_config_t::chop_config_t() { ignore_socks_destination = true; + trace_packets = false; }

chop_config_t::~chop_config_t() @@ -450,6 +452,13 @@ chop_config_t::init(int n_options, const char *const *options) n_options--; }

+ if (!strcmp(options[1], "--trace-packets")) { + options++; + n_options--; + trace_packets = true; + log_enable_timestamps(); + } + up_address = resolve_address_port(options[1], 1, listen_up, defport); if (!up_address) { log_warn("chop: invalid up address: %s", options[1]); @@ -881,11 +890,21 @@ chop_circuit_t::send_targeted(chop_conn_t *conn, size_t d, size_t p, opcode_t f, return -1; }

- char fallbackbuf[3]; + char fallbackbuf[4]; log_debug(conn, "transmitting block %u <d=%lu p=%lu f=%s>", hdr.seqno(), (unsigned long)hdr.dlen(), (unsigned long)hdr.plen(), opname(hdr.opcode(), fallbackbuf));

+ if (config->trace_packets) + fprintf(stderr, "T:%.4f: ckt %u <ntp %u outq %lu>: send %lu <d=%lu p=%lu f=%s>\n", + log_get_timestamp(), this->serial, + this->recv_queue.window(), + (unsigned long)evbuffer_get_length(bufferevent_get_input(this->up_buffer)), + (unsigned long)hdr.seqno(), + (unsigned long)hdr.dlen(), + (unsigned long)hdr.plen(), + opname(hdr.opcode(), fallbackbuf)); + if (conn->send(block)) { evbuffer_free(block); return -1; @@ -1292,6 +1311,19 @@ chop_conn_t::recv() (unsigned long)hdr.plen(), opname(hdr.opcode(), fallbackbuf), c[9], c[10], c[11], c[12], c[13], c[14], c[15]); + + if (config->trace_packets) + fprintf(stderr, "T:%.4f: ckt %u <ntp %u outq %lu>: recv-error " + "%lu <d=%lu p=%lu f=%s c=%02x%02x%02x%02x%02x%02x%02x>\n", + log_get_timestamp(), upstream->serial, + upstream->recv_queue.window(), + (unsigned long)evbuffer_get_length(bufferevent_get_input(upstream->up_buffer)), + (unsigned long)hdr.seqno(), + (unsigned long)hdr.dlen(), + (unsigned long)hdr.plen(), + opname(hdr.opcode(), fallbackbuf), + c[9], c[10], c[11], c[12], c[13], c[14], c[15]); + return -1; } if (avail < hdr.total_len()) { @@ -1319,6 +1351,16 @@ chop_conn_t::recv() hdr.seqno(), (unsigned long)hdr.dlen(), (unsigned long)hdr.plen(), opname(hdr.opcode(), fallbackbuf));

+ if (config->trace_packets) + fprintf(stderr, "T:%.4f: ckt %u <ntp %u outq %lu>: recv %lu <d=%lu p=%lu f=%s>\n", + log_get_timestamp(), upstream->serial, + upstream->recv_queue.window(), + (unsigned long)evbuffer_get_length(bufferevent_get_input(upstream->up_buffer)), + (unsigned long)hdr.seqno(), + (unsigned long)hdr.dlen(), + (unsigned long)hdr.plen(), + opname(hdr.opcode(), fallbackbuf)); + evbuffer *data = evbuffer_new(); if (!data || (hdr.dlen() && evbuffer_add(data, decodebuf, hdr.dlen()))) { log_warn(this, "failed to extract data from decode buffer"); diff --git a/src/util.cc b/src/util.cc index 4fe576a..3900f21 100644 --- a/src/util.cc +++ b/src/util.cc @@ -461,8 +461,8 @@ log_open(const char *filename) if (!log_dest) return -1;

+ setvbuf(log_dest, 0, _IONBF, 0); fputs("\nBrand new log:\n", log_dest); - fflush(log_dest);

return 0; } @@ -494,6 +494,7 @@ log_set_method(int method, const char *filename) return 0;

case LOG_METHOD_STDERR: + setvbuf(stderr, 0, _IONBF, 0); log_dest = stderr; return 0;

@@ -525,8 +526,20 @@ log_set_min_severity(const char* sev_string) void log_enable_timestamps() { - log_timestamps = true; - gettimeofday(&log_ts_base, 0); + if (!log_timestamps) { + log_timestamps = true; + gettimeofday(&log_ts_base, 0); + } +} + +/** Get a timestamp, as a floating-point number of seconds. */ +double +log_get_timestamp() +{ + struct timeval now, delta; + gettimeofday(&now, 0); + timeval_subtract(&now, &log_ts_base, &delta); + return delta.tv_sec + double(delta.tv_usec) / 1e6; }

/** True if the minimum log severity is "debug". Used in a few places @@ -554,7 +567,6 @@ logv(int severity, const char *format, va_list ap)

vfprintf(log_dest, format, ap); putc('\n', log_dest); - fflush(log_dest); }

static bool @@ -567,13 +579,8 @@ logpfx(int severity, const char *fn) if (!log_dest || severity < log_min_sev) return false;

- if (log_timestamps) { - struct timeval now, delta; - gettimeofday(&now, 0); - timeval_subtract(&now, &log_ts_base, &delta); - fprintf(log_dest, "%.4f ", - delta.tv_sec + double(delta.tv_usec) / 1e6); - } + if (log_timestamps) + fprintf(log_dest, "%.4f ", log_get_timestamp());

fprintf(log_dest, "[%s] ", sev_to_string(severity)); if (log_min_sev == LOG_SEV_DEBUG && fn) diff --git a/src/util.h b/src/util.h index 62908d1..ab4038a 100644 --- a/src/util.h +++ b/src/util.h @@ -178,6 +178,10 @@ int log_set_min_severity(const char* sev_string); /** Request timestamps on all log messages. */ void log_enable_timestamps();

+/** Get a timestamp consistent with the timestamps used for log messages. + You must have called log_enable_timestamps to use this. */ +double log_get_timestamp(); + /** True if debug messages are being logged. Guard expensive debugging checks with this, to avoid doing useless work when the messages are just going to be thrown away anyway. */