From 41ec2ae79c9b00e1fc4eef286a6f0dde970dc5d1 Mon Sep 17 00:00:00 2001 From: frekky Date: Sun, 4 Oct 2015 22:13:47 +0800 Subject: [PATCH] Added statistics printout and command line option --- src/client.c | 222 +++++++++++++++++++++++++++++++++++---------------- src/client.h | 3 + src/iodine.c | 11 ++- 3 files changed, 163 insertions(+), 73 deletions(-) diff --git a/src/client.c b/src/client.c index b9647f6..4c37f2f 100644 --- a/src/client.c +++ b/src/client.c @@ -60,7 +60,9 @@ #include "util.h" #include "client.h" +/* Output flags for debug and time between stats update */ int debug; +int stats; static int running; static const char *password; @@ -98,11 +100,20 @@ static int autodetect_server_timeout; static time_t rtt_total_ms; static size_t num_immediate; -/* Query statistics */ +/* Connection statistics */ static size_t num_timeouts; static size_t num_untracked; -static size_t send_query_sendcnt = -1; -static size_t send_query_recvcnt = -1; +static size_t num_servfail; +static size_t num_badip; +static size_t num_init_queries; +static size_t num_sent; +static size_t num_recv; +static size_t send_query_sendcnt = 0; +static size_t send_query_recvcnt = 0; + +static size_t num_frags_sent; +static size_t num_frags_recv; +static size_t num_pings; /* My userid at the server */ static char userid; @@ -169,6 +180,9 @@ client_init() maxfragsize_up = 100; + num_immediate = 1; + rtt_total_ms = 1000; + outbuf = NULL; inbuf = NULL; pending_queries = NULL; @@ -322,6 +336,48 @@ client_rotate_nameserver() fprintf(stderr, "\n");\ } +static void +update_server_timeout(int dns_fd, int handshake) +/* Calculate server timeout based on average RTT, send ping "handshake" to set */ +{ + time_t rtt_ms; + static size_t num_rtt_timeouts = 0; + + /* Get average RTT in ms */ + rtt_ms = rtt_total_ms / num_immediate; + if (rtt_ms >= max_timeout_ms) { + num_rtt_timeouts++; + if (num_rtt_timeouts < 3) { + fprintf(stderr, "Target interval of %ld ms less than average round-trip of " + "%ld ms! Try increasing interval with -I.\n", max_timeout_ms, rtt_ms); + } else { + max_timeout_ms = server_timeout_ms; + if (server_timeout_ms > rtt_ms) { + server_timeout_ms -= rtt_ms; + if (lazymode) + fprintf(stderr, "Adjusting server timeout to %ld ms, target interval %ld ms.\n", + server_timeout_ms, max_timeout_ms); + } else { + server_timeout_ms = 0; + fprintf(stderr, "Switching off lazy mode to keep timeouts below target interval (%ld ms).", + max_timeout_ms); + handshake_switch_options(dns_fd, 0, compression_down, downenc); + } + + num_rtt_timeouts = 0; + } + } else { + /* Set server timeout based on target interval and RTT */ + server_timeout_ms = max_timeout_ms - rtt_ms; + } + + if (!handshake) + return; + + /* Send ping handshake to set server timeout/lazymode */ + send_ping(dns_fd, 1, -1); +} + static void check_pending_queries() /* Updates pending queries list */ @@ -330,7 +386,7 @@ check_pending_queries() struct timeval now, qtimeout, max_timeout; gettimeofday(&now, NULL); /* Max timeout for queries is max interval + 1 second extra */ - max_timeout = ms_to_timeval(max_timeout_ms); + max_timeout = ms_to_timeval(max_timeout_ms + 1000); for (int i = 0; i < PENDING_QUERIES_LENGTH; i++) { if (pending_queries[i].time.tv_sec > 0 && pending_queries[i].id >= 0) { timeradd(&pending_queries[i].time, &max_timeout, &qtimeout); @@ -383,11 +439,9 @@ query_sent_now(int id) } static void -got_response(int id, int immediate) +got_response(int id, int immediate, int dns_fd) { struct timeval now, rtt; - time_t rtt_ms; - static size_t num_rtt_timeouts; gettimeofday(&now, NULL); QTRACK_DEBUG(4, "Got answer id %d (%s)", id, immediate ? "immediate" : "lazy"); @@ -412,25 +466,8 @@ got_response(int id, int immediate) rtt_total_ms += timeval_to_ms(&rtt); num_immediate++; - if (autodetect_server_timeout) { - /* Get average RTT in ms */ - rtt_ms = rtt_total_ms / num_immediate; - if (rtt_ms >= max_timeout_ms) { - num_rtt_timeouts++; - if (num_rtt_timeouts < 3) { - fprintf(stderr, "Preferred interval of %lu ms less than average round-trip of " - "%lu ms! Try increasing interval with -I.\n", max_timeout_ms, rtt_ms); - } else { - server_timeout_ms = max_timeout_ms; - max_timeout_ms += rtt_ms; - if (lazymode) - fprintf(stderr, "Adjusting server timeout to %lu ms.\n", server_timeout_ms); - num_rtt_timeouts = 0; - } - } else { - server_timeout_ms = max_timeout_ms - rtt_ms; - } - } + if (autodetect_server_timeout) + update_server_timeout(dns_fd, 0); } /* Remove query info from buffer to mark it as answered */ @@ -487,29 +524,32 @@ send_query(int fd, uint8_t *hostname) (Can't very well do this anywhere else; this is the only place we'll reliably get to in such situations.) */ + num_sent++; if (send_query_sendcnt >= 0 && send_query_sendcnt < 100 && lazymode) { send_query_sendcnt++; - if ((send_query_sendcnt > 6 && send_query_recvcnt <= 0) || - (send_query_sendcnt > 10 && 4 * send_query_recvcnt < send_query_sendcnt)) { - if (server_timeout_ms > 500 && autodetect_server_timeout) { - server_timeout_ms -= 200; - double secs = (double) server_timeout_ms / 1000.0; - fprintf(stderr, "Receiving too few answers. Setting server timeout to %fs (-I%f)\n", secs, secs); + if ((send_query_sendcnt > windowsize_down && send_query_recvcnt <= 0) || + (send_query_sendcnt > 2 * windowsize_down && 4 * send_query_recvcnt < send_query_sendcnt)) { + if (max_timeout_ms > 500 && autodetect_server_timeout) { + max_timeout_ms -= 500; + double secs = (double) max_timeout_ms / 1000.0; + fprintf(stderr, "Receiving too few answers. Setting target timeout to %.1fs (-I%.1f)\n", secs, secs); + /* restart counting */ send_query_sendcnt = 0; send_query_recvcnt = 0; - rtt_total_ms = 1000; - num_immediate = 1; - /* TODO: reduce windowsize due to DNS server dropping queries */ - send_ping(fd, 1, -1); + if (rtt_total_ms / num_immediate < 1000) { + rtt_total_ms = 1000; + num_immediate = 1; + } + } else if (lazymode && autodetect_server_timeout) { fprintf(stderr, "Receiving too few answers. Will try to switch lazy mode off, but that may not" " always work any more. Start with -L0 next time on this network."); lazymode = 0; server_timeout_ms = 0; - handshake_switch_options(fd, 0, compression_down, downenc); } + update_server_timeout(fd, 1); } } return q.id; @@ -558,6 +598,7 @@ send_packet(int fd, char cmd, const uint8_t *data, const size_t datalen) void send_ping(int fd, int ping_response, int ack) { + num_pings++; if (conn == CONN_DNS_NULL) { uint8_t data[11]; int id; @@ -651,6 +692,7 @@ send_next_frag(int fd) query_sent_now(id); window_tick(outbuf); + num_frags_sent++; } static void @@ -899,7 +941,7 @@ read_dns_withq(int dns_fd, int tun_fd, uint8_t *buf, size_t buflen, struct query } } -static int +int handshake_waitdns(int dns_fd, char *buf, size_t buflen, char cmd, int timeout) /* Wait for DNS reply fitting to our latest query and returns it. Returns length of reply = #bytes used in buf. @@ -985,7 +1027,7 @@ handshake_waitdns(int dns_fd, char *buf, size_t buflen, char cmd, int timeout) return -1; } -static int +int parse_data(uint8_t *data, size_t len, fragment *f, int *immediate) { size_t headerlen = DOWNSTREAM_HDR; @@ -1011,7 +1053,6 @@ parse_data(uint8_t *data, size_t len, fragment *f, int *immediate) if (len < headerlen) return -1; /* invalid packet - continue */ /* Parse data/ping header */ - /* TODO: do something with wsize/start params in ping */ dn_wsize = data[3]; up_wsize = data[4]; dn_start_seq = data[5]; @@ -1072,11 +1113,9 @@ tunnel_tun(int tun_fd, int dns_fd) static int tunnel_dns(int tun_fd, int dns_fd) { - static long packrecv = 0; - static long packrecv_servfail = 0; static struct query q; size_t datalen, buflen; - static uint8_t buf[64*1024], cbuf[64*1024]; + static uint8_t buf[64*1024], cbuf[64*1024], *data; static fragment f; int read, compressed, res, immediate; @@ -1106,25 +1145,28 @@ tunnel_dns(int tun_fd, int dns_fd) if (read < 0) write_dns_error(&q, 0); - if (read < 0 && q.rcode == SERVFAIL && lazymode && server_timeout_ms > 500) { - if (packrecv < 500 && packrecv_servfail < 4) { - packrecv_servfail++; - fprintf(stderr, "Hmm, that's %ld SERVFAILs. Your data should still go through...", packrecv_servfail); - } else if (packrecv < 500 && packrecv_servfail >= 4 && autodetect_server_timeout) { - packrecv_servfail++; + if (read < 0 && q.rcode == SERVFAIL && lazymode && max_timeout_ms > 500) { + num_servfail++; + + if (send_query_recvcnt < 500 && num_servfail < 4) { + fprintf(stderr, "Hmm, that's %ld SERVFAILs. Your data should still go through...", num_servfail); + } else if (send_query_recvcnt < 500 && num_servfail >= 4 && autodetect_server_timeout) { server_timeout_ms -= 500; double server_timeout = (float) server_timeout_ms / 1000.0; - fprintf(stderr, "%ld SERVFAILs is too many. Setting server timeout to %f to hopefully reduce SERVFAILs." - " But just ignore them if data still comes through. (Use -I%f next time on this network.)", - packrecv_servfail, server_timeout, server_timeout); + fprintf(stderr, "Exceeded acceptable limit for SERVFAILs (%ld), setting " + "timeout to %.1f secs. (use -I%.1f next time on this network)\n", + num_servfail, server_timeout, server_timeout); + + /* Reset query counts stats */ send_query_sendcnt = 0; send_query_recvcnt = 0; - rtt_total_ms = 1000; - num_immediate = 1; - send_ping(dns_fd, 0, -1); - } else if (packrecv >= 500 && packrecv_servfail > 0) { - fprintf(stderr, "(Sorry, stopped counting; try -I1 if you experience hiccups.)"); - packrecv_servfail = 0; + if (rtt_total_ms / num_immediate < 1000) { + /* only reset avg RTT if it might be too small (TODO trust the statistics) */ + rtt_total_ms = 1000; + num_immediate = 1; + } + + update_server_timeout(dns_fd, 1); } } @@ -1133,18 +1175,19 @@ tunnel_dns(int tun_fd, int dns_fd) } if (read == 5 && !strncmp("BADIP", (char *)cbuf, 5)) { - fprintf(stderr, "BADIP: Server rejected sender IP address (maybe iodined -c will help), or server " - "kicked us due to timeout. Will exit if no downstream data is received in 60 seconds."); + num_badip++; + if (num_badip % 5 == 1) { + fprintf(stderr, "BADIP (%ld): Server rejected sender IP address (maybe iodined -c will help), or server " + "kicked us due to timeout. Will exit if no downstream data is received in 60 seconds.", num_badip); + } return -1; /* nothing done */ } /* Okay, we have a recent downstream packet */ lastdownstreamtime = time(NULL); - if (!(packrecv & 0x10000000)) - packrecv++; - - send_query_recvcnt++; /* overflow doesn't matter */ + send_query_recvcnt++; /* unlikely we will ever overflow (2^64 queries is a LOT) */ + num_recv++; /* Decode the downstream data header and fragment-ify ready for processing */ res = parse_data(cbuf, read, &f, &immediate); @@ -1153,7 +1196,7 @@ tunnel_dns(int tun_fd, int dns_fd) res ? "PING" : "DATA", f.seqID, f.ack_other, f.compressed, f.len, f.start, f.end); /* Mark query as received */ - got_response(q.id, immediate); + got_response(q.id, immediate, dns_fd); window_ack(outbuf, f.ack_other); window_tick(outbuf); @@ -1185,6 +1228,8 @@ tunnel_dns(int tun_fd, int dns_fd) /* Downstream data traffic + get ack for that data */ next_downstream_ack = window_process_incoming_fragment(inbuf, &f); + num_frags_recv++; + datalen = window_reassemble_data(inbuf, cbuf, sizeof(cbuf), &compressed); if (datalen > 0) { if (compressed) { @@ -1196,10 +1241,13 @@ tunnel_dns(int tun_fd, int dns_fd) } else { datalen = buflen; } + data = buf; + } else { + data = cbuf; } if (datalen) - write_tun(tun_fd, buf, datalen); + write_tun(tun_fd, data, datalen); } /* Move window along after doing all data processing */ @@ -1216,6 +1264,7 @@ client_tunnel(int tun_fd, int dns_fd) int rv; int i; int sending; + time_t last_stats; if (conn != CONN_DNS_NULL) { compression_up = 1; @@ -1225,6 +1274,9 @@ client_tunnel(int tun_fd, int dns_fd) /* Incoming buffer max fragsize doesn't matter */ inbuf = window_buffer_init(64, windowsize_down, MAX_FRAGSIZE, WINDOW_RECVING); + /* init query tracking */ + num_untracked = 0; + num_pending = 0; pending_queries = calloc(PENDING_QUERIES_LENGTH, sizeof(struct query_tuple)); for (int i = 0; i < PENDING_QUERIES_LENGTH; i++) pending_queries[i].id = -1; @@ -1232,13 +1284,22 @@ client_tunnel(int tun_fd, int dns_fd) /* start counting now */ rv = 0; lastdownstreamtime = time(NULL); + last_stats = time(NULL); rtt_total_ms = 1000; num_immediate = 1; + + /* reset connection statistics */ + num_init_queries = MAX(send_query_recvcnt, send_query_sendcnt); + num_badip = 0; + num_servfail = 0; num_timeouts = 0; - num_untracked = 0; - num_pending = 0; send_query_recvcnt = 0; send_query_sendcnt = 0; + num_sent = 0; + num_recv = 0; + num_frags_sent = 0; + num_frags_recv = 0; + num_pings = 0; if (debug >= 5) window_debug = debug - 3; @@ -1246,8 +1307,7 @@ client_tunnel(int tun_fd, int dns_fd) while (running) { tv = ms_to_timeval(max_timeout_ms); - /* TODO: adjust min send interval based on DNS server droppiness - * (eg. from sending lots of requests simultaneously) + /* TODO: detect DNS servers which drop frequent requests * TODO: adjust number of pending queries based on current data rate */ sending = window_sending(outbuf); check_pending_queries(); @@ -1268,6 +1328,26 @@ client_tunnel(int tun_fd, int dns_fd) send_ping_soon = 0; } + if (stats) { + if (difftime(time(NULL), last_stats) >= stats) { + /* print useful statistics report */ + fprintf(stderr, "\n========== iodine connection statistics (user %1d) ==========\n", userid); + fprintf(stderr, " Queries sent: %8lu" " answered: %8lu" " SERVFAILs: %4lu\n", + num_sent, num_recv, num_servfail); + fprintf(stderr, " during init: %4lu IP rejected: %4lu untracked: %4lu\n", + num_init_queries, num_badip, num_untracked); + fprintf(stderr, " Average round-trip time: %4ld ms immediate answers: %5lu\n", + rtt_total_ms / num_immediate, num_immediate); + fprintf(stderr, " query timeouts: %4lu target: %4ld ms server: %4ld ms\n", + num_timeouts, max_timeout_ms, server_timeout_ms); + fprintf(stderr, " Resent fragments up: %4u downstream out of window: %4u\n", + outbuf->resends, inbuf->oos); + fprintf(stderr, " TX fragments: %8lu" " RX: %8lu" " pings: %8lu" "\n\n", + num_frags_sent, num_frags_recv, num_pings); + last_stats = time(NULL); + } + } + if (send_ping_soon) { tv.tv_sec = 0; tv.tv_usec = send_ping_soon * 1000; @@ -1284,7 +1364,7 @@ client_tunnel(int tun_fd, int dns_fd) i = select(MAX(tun_fd, dns_fd) + 1, &fds, NULL, NULL, &tv); if (difftime(time(NULL), lastdownstreamtime) > 60) { - warnx("No downstream data received in 60 seconds, shutting down."); + fprintf(stderr, "No downstream data received in 60 seconds, shutting down.\n"); running = 0; } diff --git a/src/client.h b/src/client.h index 5e7ac0b..45b5079 100644 --- a/src/client.h +++ b/src/client.h @@ -19,6 +19,7 @@ #define __CLIENT_H__ extern int debug; +extern int stats; #define PENDING_QUERIES_LENGTH (MAX(windowsize_up, windowsize_down) * 3) @@ -49,6 +50,8 @@ void client_set_hostname_maxlen(size_t i); int client_handshake(int dns_fd, int raw_mode, int autodetect_frag_size, int fragsize); int client_tunnel(int tun_fd, int dns_fd); +int parse_data(uint8_t *data, size_t len, fragment *f, int *immediate); +int handshake_waitdns(int dns_fd, char *buf, size_t buflen, char cmd, int timeout); void handshake_switch_options(int dns_fd, int lazy, int compression, char denc); void send_ping(int fd, int ping_response, int ack); diff --git a/src/iodine.c b/src/iodine.c index 86f492c..291ade2 100644 --- a/src/iodine.c +++ b/src/iodine.c @@ -69,7 +69,7 @@ print_usage() { extern char *__progname; - fprintf(stderr, "Usage: %s [-v] [-h] [-f] [-r] [-u user] [-t chrootdir] [-d device] " + fprintf(stderr, "Usage: %s [-v] [-h] [-V sec] [-f] [-r] [-u user] [-t chrootdir] [-d device] " "[-w downfrags] [-W upfrags] [-i sec] [-I sec] [-c 0|1] [-C 0|1] " "[-P password] [-m maxfragsize] [-M maxlen] [-T type] [-O enc] [-L 0|1] " "[-z context] [-F pidfile] topdomain [nameserver1 [nameserver2 [nameserverN ...]]]\n", __progname); @@ -110,6 +110,7 @@ help() fprintf(stderr, "Other options:\n"); fprintf(stderr, " -v to print version info and exit\n"); fprintf(stderr, " -h to print this help and exit\n"); + fprintf(stderr, " -V sec to print connection statistics at specified intervals\n"); fprintf(stderr, " -f to keep running in foreground\n"); fprintf(stderr, " -D enable debug mode (add more D's to increase debug level)\n"); fprintf(stderr, " -u name to drop privileges and run as user 'name'\n"); @@ -198,6 +199,7 @@ main(int argc, char **argv) device = NULL; pidfile = NULL; debug = 0; + stats = 0; autodetect_frag_size = 1; max_downstream_frag_size = 3072; @@ -230,7 +232,7 @@ main(int argc, char **argv) __progname++; #endif - while ((choice = getopt(argc, argv, "46vfDhrcCu:t:d:R:P:w:W:m:M:F:T:O:L:I:")) != -1) { + while ((choice = getopt(argc, argv, "46vfDhrV:c:C:i:u:t:d:R:P:w:W:m:M:F:T:O:L:I:")) != -1) { switch(choice) { case '4': nameserv_family = AF_INET; @@ -242,6 +244,11 @@ main(int argc, char **argv) version(); /* NOTREACHED */ break; + case 'V': + stats = atoi(optarg); + if (stats < 0) + stats = 0; + break; case 'f': foreground = 1; break;