From eee0d14a69e85f45e1e01e010c77d2d05389c43b Mon Sep 17 00:00:00 2001 From: frekky Date: Tue, 4 Jul 2017 21:40:56 +0200 Subject: [PATCH] improve debug output & remove unnecessary window_ticks --- src/client.c | 14 ++++++++++---- src/server.c | 34 ++++++++++++++++++---------------- 2 files changed, 28 insertions(+), 20 deletions(-) diff --git a/src/client.c b/src/client.c index 8838a46..20ddc09 100644 --- a/src/client.c +++ b/src/client.c @@ -135,7 +135,8 @@ client_set_hostname_maxlen(size_t i) { if (i <= 0xFF && i != this.hostname_maxlen) { this.hostname_maxlen = i; - this.maxfragsize_up = get_raw_length_from_dns(this.hostname_maxlen - UPSTREAM_HDR, this.dataenc, this.topdomain); + this.maxfragsize_up = get_raw_length_from_dns(this.hostname_maxlen - UPSTREAM_HDR, + this.dataenc, this.topdomain); if (this.outbuf) window_buffer_resize(this.outbuf, this.outbuf->length, this.maxfragsize_up); } @@ -1147,8 +1148,10 @@ tunnel_dns() ping ? "PING" : "DATA", f.seqID, f.ack_other, f.compressed, f.len, f.start, f.end); - window_ack(this.outbuf, f.ack_other); - window_tick(this.outbuf); + if (f.ack_other >= 0) { + window_ack(this.outbuf, f.ack_other); + window_tick(this.outbuf); + } /* respond to TCP forwarding errors by shutting down */ if (error && this.use_remote_forward) { @@ -1276,6 +1279,8 @@ client_tunnel() else if (this.num_pending < 1 && !this.lazymode) total = MAX(total, 1); + QTRACK_DEBUG(2, "sending=%d, total=%d, next_ack=%d, outbuf.n=%" L "u", + sending, total, this.next_downstream_ack, this.outbuf->numitems); /* Upstream traffic - this is where all ping/data queries are sent */ if (sending > 0 || total > 0 || this.next_downstream_ack >= 0) { @@ -1284,7 +1289,8 @@ client_tunnel() send_next_frag(); } else { /* Send ping if we didn't send anything yet */ - send_ping(0, this.next_downstream_ack, (this.num_pings > 20 && this.num_pings % 50 == 0), 0); + send_ping(0, this.next_downstream_ack, (this.num_pings > 20 && + this.num_pings % 50 == 0), 0); this.next_downstream_ack = -1; } diff --git a/src/server.c b/src/server.c index b834bda..2856be2 100644 --- a/src/server.c +++ b/src/server.c @@ -260,10 +260,9 @@ qmem_max_wait(int *touser, struct query **sendq) struct timeval now, timeout, soonest, tmp, age, nextresend; soonest.tv_sec = 10; soonest.tv_usec = 0; - int userid, qnum, nextuser = -1, immediate, resend = 0; + int userid, nextuser = -1, resend = 0; struct query *q = NULL, *nextq = NULL; size_t sending, total, sent; - time_t age_ms; struct tun_user *u; gettimeofday(&now, NULL); @@ -299,7 +298,7 @@ qmem_max_wait(int *touser, struct query **sendq) sending = total; sent = 0; - qnum = u->qmem.start_pending; + int qnum = u->qmem.start_pending; for (; qnum != u->qmem.end; qnum = (qnum + 1) % QMEM_LEN) { q = &u->qmem.queries[qnum].q; @@ -311,18 +310,16 @@ qmem_max_wait(int *touser, struct query **sendq) * - user has pending data (always data) * - user has pending ACK (either) */ timersub(&now, &q->time_recv, &age); - age_ms = timeval_to_ms(&age); + time_t age_ms = timeval_to_ms(&age); /* only consider "immediate" when age is negligible */ - immediate = llabs(age_ms) <= 10; + int immediate = llabs(age_ms) <= 10; - QMEM_DEBUG(3, userid, "Auto response to cached query: ID %d, %ld ms old (%s), timeout %ld ms", - q->id, age_ms, immediate ? "immediate" : "lazy", timeval_to_ms(&u->dns_timeout)); + QMEM_DEBUG(3, userid, "ANSWER: ID %d, age=%ldms (imm=%d), timeout %ldms, ACK %d," + " sent %" L "u/%" L "u (+%" L "u)", q->id, age_ms, immediate, + timeval_to_ms(&u->dns_timeout), u->next_upstream_ack, sent, total, sending); sent++; - QMEM_DEBUG(4, userid, "ANSWER q id %d, ACK %d; sent %" L "u of %" L "u + sending another %" L "u", - q->id, u->next_upstream_ack, sent, total, sending); - send_data_or_ping(userid, q, 0, immediate, NULL); if (sending > 0) @@ -345,15 +342,17 @@ qmem_max_wait(int *touser, struct query **sendq) if (server.debug >= 5) { time_t soonest_ms = timeval_to_ms(&soonest); if (nextq && nextuser >= 0) { - QMEM_DEBUG(5, nextuser, "can wait for %" L "u ms, will send id %d", soonest_ms, nextq->id); + QMEM_DEBUG(5, nextuser, "can wait for %" L "d ms, will send id %d", soonest_ms, nextq->id); } else { if (nextuser < 0) nextuser = 0; if (soonest_ms != 10000 && resend) { /* only if resending some frags */ - QMEM_DEBUG(5, nextuser, "Resending some fragments") + QMEM_DEBUG(5, nextuser, "Resending some fragments, soonest = %d ms", soonest_ms); + if (soonest_ms == 0) + QMEM_DEBUG(5, nextuser, "soonest_ms == 0! tv=%ds,%dus", soonest.tv_sec, soonest.tv_usec); } else { - QMEM_DEBUG(2, nextuser, "Don't need to send anything to any users, waiting %" L "u ms", soonest_ms); + QMEM_DEBUG(2, nextuser, "Don't need to send anything to any users, waiting %" L "d ms", soonest_ms); } } } @@ -499,6 +498,7 @@ send_data_or_ping(int userid, struct query *q, int ping, int immediate, char *tc } if (datalen + headerlen > sizeof(pkt)) { warnx("send_data_or_ping: fragment too large to send! (%" L "u)", datalen); + window_tick(out); return; } if (f) { @@ -521,8 +521,10 @@ user_process_incoming_data(int userid, int ack) uint8_t compressed = 0; int can_reassemble = 1; - window_ack(users[userid].outgoing, ack); - window_tick(users[userid].outgoing); + if (ack >= 0) { + window_ack(users[userid].outgoing, ack); + window_tick(users[userid].outgoing); + } while (can_reassemble == 1) { datalen = sizeof(pkt); @@ -821,7 +823,7 @@ server_tunnel() if(i < 0) { if (server.running) - warn("select"); + warn("select < 0"); return 1; }