#include <unistd.h>
#include <sys/time.h>
#include <sys/socket.h>
+#include <time.h>
#include "utcp_priv.h"
#ifdef UTCP_DEBUG
#include <stdarg.h>
-static void debug(const char *format, ...) {
+#ifndef UTCP_DEBUG_DATALEN
+#define UTCP_DEBUG_DATALEN 20
+#endif
+
+static void debug(struct utcp_connection *c, const char *format, ...) {
+ struct timespec tv;
+ char buf[1024];
+ int len;
+
+ clock_gettime(CLOCK_REALTIME, &tv);
+ len = snprintf(buf, sizeof(buf), "%ld.%06lu %u:%u ", (long)tv.tv_sec, tv.tv_nsec / 1000, c ? c->src : 0, c ? c->dst : 0);
va_list ap;
va_start(ap, format);
- vfprintf(stderr, format, ap);
+ len += vsnprintf(buf + len, sizeof(buf) - len, format, ap);
va_end(ap);
+
+ if(len > 0 && (size_t)len < sizeof(buf)) {
+ fwrite(buf, len, 1, stderr);
+ }
}
-static void print_packet(struct utcp *utcp, const char *dir, const void *pkt, size_t len) {
+static void print_packet(struct utcp_connection *c, const char *dir, const void *pkt, size_t len) {
struct hdr hdr;
if(len < sizeof(hdr)) {
- debug("%p %s: short packet (%lu bytes)\n", utcp, dir, (unsigned long)len);
+ debug(c, "%s: short packet (%lu bytes)\n", dir, (unsigned long)len);
return;
}
memcpy(&hdr, pkt, sizeof(hdr));
- debug("%p %s: len=%lu, src=%u dst=%u seq=%u ack=%u wnd=%u aux=%x ctl=", utcp, dir, (unsigned long)len, hdr.src, hdr.dst, hdr.seq, hdr.ack, hdr.wnd, hdr.aux);
- if(hdr.ctl & SYN) {
- debug("SYN");
- }
+ uint32_t datalen;
- if(hdr.ctl & RST) {
- debug("RST");
- }
-
- if(hdr.ctl & FIN) {
- debug("FIN");
- }
-
- if(hdr.ctl & ACK) {
- debug("ACK");
+ if(len > sizeof(hdr)) {
+ datalen = min(len - sizeof(hdr), UTCP_DEBUG_DATALEN);
+ } else {
+ datalen = 0;
}
- if(len > sizeof(hdr)) {
- uint32_t datalen = len - sizeof(hdr);
- const uint8_t *data = (uint8_t *)pkt + sizeof(hdr);
- char str[datalen * 2 + 1];
- char *p = str;
- for(uint32_t i = 0; i < datalen; i++) {
- *p++ = "0123456789ABCDEF"[data[i] >> 4];
- *p++ = "0123456789ABCDEF"[data[i] & 15];
- }
+ const uint8_t *data = (uint8_t *)pkt + sizeof(hdr);
+ char str[datalen * 2 + 1];
+ char *p = str;
- *p = 0;
-
- debug(" data=%s", str);
+ for(uint32_t i = 0; i < datalen; i++) {
+ *p++ = "0123456789ABCDEF"[data[i] >> 4];
+ *p++ = "0123456789ABCDEF"[data[i] & 15];
}
- debug("\n");
+ *p = 0;
+
+ debug(c, "%s: len %lu src %u dst %u seq %u ack %u wnd %u aux %x ctl %s%s%s%s data %s\n",
+ dir, (unsigned long)len, hdr.src, hdr.dst, hdr.seq, hdr.ack, hdr.wnd, hdr.aux,
+ hdr.ctl & SYN ? "SYN" : "",
+ hdr.ctl & RST ? "RST" : "",
+ hdr.ctl & FIN ? "FIN" : "",
+ hdr.ctl & ACK ? "ACK" : "",
+ str
+ );
}
static void debug_cwnd(struct utcp_connection *c) {
- debug("snd.cwnd = %u\n", c->snd.cwnd);
+ debug(c, "snd.cwnd %u snd.ssthresh %u\n", c->snd.cwnd, c->snd.ssthresh);
}
#else
#define debug(...) do {} while(0)
timerclear(&c->conn_timeout);
}
- debug("%p new state: %s\n", c->utcp, strstate[state]);
+ debug(c, "state %s\n", strstate[state]);
}
static bool fin_wanted(struct utcp_connection *c, uint32_t seq) {
// Store data into the buffer
static ssize_t buffer_put_at(struct buffer *buf, size_t offset, const void *data, size_t len) {
- debug("buffer_put_at %lu %lu %lu\n", (unsigned long)buf->used, (unsigned long)offset, (unsigned long)len);
+ debug(NULL, "buffer_put_at %lu %lu %lu\n", (unsigned long)buf->used, (unsigned long)offset, (unsigned long)len);
size_t required = offset + len;
c->snd.nxt = c->snd.iss + 1;
c->snd.last = c->snd.nxt;
c->snd.cwnd = (utcp->mtu > 2190 ? 2 : utcp->mtu > 1095 ? 3 : 4) * utcp->mtu;
+#if UTCP_DEBUG
+ c->snd.ssthresh = c->sndbuf.maxsize;
+#else
c->snd.ssthresh = ~0;
+#endif
debug_cwnd(c);
c->utcp = utcp;
// Update RTT variables. See RFC 6298.
static void update_rtt(struct utcp_connection *c, uint32_t rtt) {
if(!rtt) {
- debug("invalid rtt\n");
+ debug(c, "invalid rtt\n");
return;
}
utcp->rto = MAX_RTO;
}
- debug("rtt %u srtt %u rttvar %u rto %u\n", rtt, utcp->srtt, utcp->rttvar, utcp->rto);
+ debug(c, "rtt %u srtt %u rttvar %u rto %u\n", rtt, utcp->srtt, utcp->rttvar, utcp->rto);
}
static void start_retransmit_timer(struct utcp_connection *c) {
c->rtrx_timeout.tv_sec++;
}
- debug("timeout set to %lu.%06lu (%u)\n", c->rtrx_timeout.tv_sec, c->rtrx_timeout.tv_usec, c->utcp->rto);
+ debug(c, "rtrx_timeout %ld.%06lu\n", c->rtrx_timeout.tv_sec, c->rtrx_timeout.tv_usec);
}
static void stop_retransmit_timer(struct utcp_connection *c) {
timerclear(&c->rtrx_timeout);
- debug("timeout cleared\n");
+ debug(c, "rtrx_timeout cleared\n");
}
struct utcp_connection *utcp_connect_ex(struct utcp *utcp, uint16_t dst, utcp_recv_t recv, void *priv, uint32_t flags) {
set_state(c, SYN_SENT);
- print_packet(utcp, "send", &pkt, sizeof(pkt));
+ print_packet(c, "send", &pkt, sizeof(pkt));
utcp->send(utcp, &pkt, sizeof(pkt));
gettimeofday(&c->conn_timeout, NULL);
void utcp_accept(struct utcp_connection *c, utcp_recv_t recv, void *priv) {
if(c->reapable || c->state != SYN_RECEIVED) {
- debug("Error: accept() called on invalid connection %p in state %s\n", c, strstate[c->state]);
+ debug(c, "accept() called on invalid connection in state %s\n", c, strstate[c->state]);
return;
}
- debug("%p accepted, %p %p\n", c, recv, priv);
+ debug(c, "accepted %p %p\n", c, recv, priv);
c->recv = recv;
c->priv = priv;
set_state(c, ESTABLISHED);
}
}
- debug("cwndleft = %d, left = %d\n", cwndleft, left);
+ debug(c, "cwndleft %d left %d\n", cwndleft, left);
if(!left && !sendatleastone) {
return;
// Start RTT measurement
gettimeofday(&c->rtt_start, NULL);
c->rtt_seq = pkt->hdr.seq + seglen;
- debug("Starting RTT measurement, expecting ack %u\n", c->rtt_seq);
+ debug(c, "starting RTT measurement, expecting ack %u\n", c->rtt_seq);
}
- print_packet(c->utcp, "send", pkt, sizeof(pkt->hdr) + seglen);
+ print_packet(c, "send", pkt, sizeof(pkt->hdr) + seglen);
c->utcp->send(c->utcp, pkt, sizeof(pkt->hdr) + seglen);
} while(left);
ssize_t utcp_send(struct utcp_connection *c, const void *data, size_t len) {
if(c->reapable) {
- debug("Error: send() called on closed connection %p\n", c);
+ debug(c, "send() called on closed connection\n");
errno = EBADF;
return -1;
}
switch(c->state) {
case CLOSED:
case LISTEN:
- debug("Error: send() called on unconnected connection %p\n", c);
+ debug(c, "send() called on unconnected connection\n");
errno = ENOTCONN;
return -1;
case CLOSING:
case LAST_ACK:
case TIME_WAIT:
- debug("Error: send() called on closing connection %p\n", c);
+ debug(c, "send() called on closed connection\n");
errno = EPIPE;
return -1;
}
static void fast_retransmit(struct utcp_connection *c) {
if(c->state == CLOSED || c->snd.last == c->snd.una) {
- debug("fast_retransmit() called but nothing to retransmit!\n");
+ debug(c, "fast_retransmit() called but nothing to retransmit!\n");
return;
}
}
buffer_copy(&c->sndbuf, pkt->data, 0, len);
- print_packet(c->utcp, "rtrx", pkt, sizeof(pkt->hdr) + len);
+ print_packet(c, "rtrx", pkt, sizeof(pkt->hdr) + len);
utcp->send(utcp, pkt, sizeof(pkt->hdr) + len);
break;
static void retransmit(struct utcp_connection *c) {
if(c->state == CLOSED || c->snd.last == c->snd.una) {
- debug("Retransmit() called but nothing to retransmit!\n");
+ debug(c, "retransmit() called but nothing to retransmit!\n");
stop_retransmit_timer(c);
return;
}
pkt->data[1] = 0;
pkt->data[2] = 0;
pkt->data[3] = c->flags & 0x7;
- print_packet(c->utcp, "rtrx", pkt, sizeof(pkt->hdr) + 4);
+ print_packet(c, "rtrx", pkt, sizeof(pkt->hdr) + 4);
utcp->send(utcp, pkt, sizeof(pkt->hdr) + 4);
break;
pkt->hdr.seq = c->snd.nxt;
pkt->hdr.ack = c->rcv.nxt;
pkt->hdr.ctl = SYN | ACK;
- print_packet(c->utcp, "rtrx", pkt, sizeof(pkt->hdr));
+ print_packet(c, "rtrx", pkt, sizeof(pkt->hdr));
utcp->send(utcp, pkt, sizeof(pkt->hdr));
break;
debug_cwnd(c);
buffer_copy(&c->sndbuf, pkt->data, 0, len);
- print_packet(c->utcp, "rtrx", pkt, sizeof(pkt->hdr) + len);
+ print_packet(c, "rtrx", pkt, sizeof(pkt->hdr) + len);
utcp->send(utcp, pkt, sizeof(pkt->hdr) + len);
break;
* - the SACK entry is completely before ^, in that case delete it.
*/
static void sack_consume(struct utcp_connection *c, size_t len) {
- debug("sack_consume %lu\n", (unsigned long)len);
+ debug(c, "sack_consume %lu\n", (unsigned long)len);
if(len > c->rcvbuf.used) {
- debug("All SACK entries consumed");
+ debug(c, "all SACK entries consumed\n");
c->sacks[0].len = 0;
return;
}
}
for(int i = 0; i < NSACKS && c->sacks[i].len; i++) {
- debug("SACK[%d] offset %u len %u\n", i, c->sacks[i].offset, c->sacks[i].len);
+ debug(c, "SACK[%d] offset %u len %u\n", i, c->sacks[i].offset, c->sacks[i].len);
}
}
static void handle_out_of_order(struct utcp_connection *c, uint32_t offset, const void *data, size_t len) {
- debug("out of order packet, offset %u\n", offset);
+ debug(c, "out of order packet, offset %u\n", offset);
// Packet loss or reordering occured. Store the data in the buffer.
ssize_t rxd = buffer_put_at(&c->rcvbuf, offset, data, len);
// Make note of where we put it.
for(int i = 0; i < NSACKS; i++) {
if(!c->sacks[i].len) { // nothing to merge, add new entry
- debug("New SACK entry %d\n", i);
+ debug(c, "new SACK entry %d\n", i);
c->sacks[i].offset = offset;
c->sacks[i].len = rxd;
break;
} else if(offset < c->sacks[i].offset) {
if(offset + rxd < c->sacks[i].offset) { // insert before
if(!c->sacks[NSACKS - 1].len) { // only if room left
- debug("Insert SACK entry at %d\n", i);
+ debug(c, "insert SACK entry at %d\n", i);
memmove(&c->sacks[i + 1], &c->sacks[i], (NSACKS - i - 1) * sizeof(c->sacks)[i]);
c->sacks[i].offset = offset;
c->sacks[i].len = rxd;
} else {
- debug("SACK entries full, dropping packet\n");
+ debug(c, "SACK entries full, dropping packet\n");
}
break;
} else { // merge
- debug("Merge with start of SACK entry at %d\n", i);
+ debug(c, "merge with start of SACK entry at %d\n", i);
c->sacks[i].offset = offset;
break;
}
} else if(offset <= c->sacks[i].offset + c->sacks[i].len) {
if(offset + rxd > c->sacks[i].offset + c->sacks[i].len) { // merge
- debug("Merge with end of SACK entry at %d\n", i);
+ debug(c, "merge with end of SACK entry at %d\n", i);
c->sacks[i].len = offset + rxd - c->sacks[i].offset;
// TODO: handle potential merge with next entry
}
}
for(int i = 0; i < NSACKS && c->sacks[i].len; i++) {
- debug("SACK[%d] offset %u len %u\n", i, c->sacks[i].offset, c->sacks[i].len);
+ debug(c, "SACK[%d] offset %u len %u\n", i, c->sacks[i].offset, c->sacks[i].len);
}
}
static void handle_in_order(struct utcp_connection *c, const void *data, size_t len) {
// Check if we can process out-of-order data now.
if(c->sacks[0].len && len >= c->sacks[0].offset) { // TODO: handle overlap with second SACK
- debug("incoming packet len %lu connected with SACK at %u\n", (unsigned long)len, c->sacks[0].offset);
+ debug(c, "incoming packet len %lu connected with SACK at %u\n", (unsigned long)len, c->sacks[0].offset);
buffer_put_at(&c->rcvbuf, 0, data, len); // TODO: handle return value
len = max(len, c->sacks[0].offset + c->sacks[0].len);
data = c->rcvbuf.data;
return -1;
}
- print_packet(utcp, "recv", data, len);
-
// Drop packets smaller than the header
struct hdr hdr;
if(len < sizeof(hdr)) {
+ print_packet(NULL, "recv", data, len);
errno = EBADMSG;
return -1;
}
// Make a copy from the potentially unaligned data to a struct hdr
memcpy(&hdr, ptr, sizeof(hdr));
+
+ // Try to match the packet to an existing connection
+
+ struct utcp_connection *c = find_connection(utcp, hdr.dst, hdr.src);
+ print_packet(c, "recv", data, len);
+
+ // Process the header
+
ptr += sizeof(hdr);
len -= sizeof(hdr);
// Drop packets with an unknown CTL flag
if(hdr.ctl & ~(SYN | ACK | RST | FIN)) {
+ print_packet(NULL, "recv", data, len);
errno = EBADMSG;
return -1;
}
bool has_data = len || (hdr.ctl & (SYN | FIN));
- // Try to match the packet to an existing connection
-
- struct utcp_connection *c = find_connection(utcp, hdr.dst, hdr.src);
-
// Is it for a new connection?
if(!c) {
pkt.data[1] = 0;
pkt.data[2] = 0;
pkt.data[3] = c->flags & 0x7;
- print_packet(c->utcp, "send", &pkt, sizeof(hdr) + 4);
+ print_packet(c, "send", &pkt, sizeof(hdr) + 4);
utcp->send(utcp, &pkt, sizeof(hdr) + 4);
} else {
pkt.hdr.aux = 0;
- print_packet(c->utcp, "send", &pkt, sizeof(hdr));
+ print_packet(c, "send", &pkt, sizeof(hdr));
utcp->send(utcp, &pkt, sizeof(hdr));
}
} else {
return 0;
}
- debug("%p state %s\n", c->utcp, strstate[c->state]);
+ debug(c, "state %s\n", strstate[c->state]);
// In case this is for a CLOSED connection, ignore the packet.
// TODO: make it so incoming packets can never match a CLOSED connection.
if(c->state == CLOSED) {
- debug("Got packet for closed connection\n");
+ debug(c, "got packet for closed connection\n");
return 0;
}
}
if(!acceptable) {
- debug("Packet not acceptable, %u <= %u + %lu < %u\n", c->rcv.nxt, hdr.seq, (unsigned long)len, c->rcv.nxt + c->rcvbuf.maxsize);
+ debug(c, "packet not acceptable, %u <= %u + %lu < %u\n", c->rcv.nxt, hdr.seq, (unsigned long)len, c->rcv.nxt + c->rcvbuf.maxsize);
// Ignore unacceptable RST packets.
if(hdr.ctl & RST) {
}
if(hdr.ctl & ACK && (seqdiff(hdr.ack, c->snd.last) > 0 || seqdiff(hdr.ack, c->snd.una) < 0)) {
- debug("Packet ack seqno out of range, %u <= %u < %u\n", c->snd.una, hdr.ack, c->snd.una + c->sndbuf.used);
+ debug(c, "packet ack seqno out of range, %u <= %u < %u\n", c->snd.una, hdr.ack, c->snd.una + c->sndbuf.used);
// Ignore unacceptable RST packets.
if(hdr.ctl & RST) {
update_rtt(c, diff.tv_sec * 1000000 + diff.tv_usec);
c->rtt_start.tv_sec = 0;
} else if(c->rtt_seq < hdr.ack) {
- debug("Cancelling RTT measurement: %u < %u\n", c->rtt_seq, hdr.ack);
+ debug(c, "cancelling RTT measurement: %u < %u\n", c->rtt_seq, hdr.ack);
c->rtt_start.tv_sec = 0;
}
}
if(c->dupack) {
if(c->dupack >= 3) {
+ debug(c, "fast recovery ended\n");
c->snd.cwnd = c->snd.ssthresh;
}
} else {
if(!len && is_reliable(c)) {
c->dupack++;
+ debug(c, "duplicate ACK %d\n", c->dupack);
if(c->dupack == 3) {
- debug("Triplicate ACK\n");
-
// RFC 5681 fast recovery
+ debug(c, "fast recovery started\n", c->dupack);
c->snd.ssthresh = max(c->snd.cwnd / 2, utcp->mtu * 2); // eq. 4
c->snd.cwnd = min(c->snd.ssthresh + 3 * utcp->mtu, c->sndbuf.maxsize);
hdr.ctl = RST | ACK;
}
- print_packet(utcp, "send", &hdr, sizeof(hdr));
+ print_packet(c, "send", &hdr, sizeof(hdr));
utcp->send(utcp, &hdr, sizeof(hdr));
return 0;
}
int utcp_shutdown(struct utcp_connection *c, int dir) {
- debug("%p shutdown %d at %u\n", c ? c->utcp : NULL, dir, c ? c->snd.last : 0);
+ debug(c, "shutdown %d at %u\n", dir, c ? c->snd.last : 0);
if(!c) {
errno = EFAULT;
}
if(c->reapable) {
- debug("Error: shutdown() called on closed connection %p\n", c);
+ debug(c, "shutdown() called on closed connection\n");
errno = EBADF;
return -1;
}
}
if(c->reapable) {
- debug("Error: abort() called on closed connection %p\n", c);
+ debug(c, "abort() called on closed connection\n");
errno = EBADF;
return false;
}
hdr.wnd = 0;
hdr.ctl = RST;
- print_packet(c->utcp, "send", &hdr, sizeof(hdr));
+ print_packet(c, "send", &hdr, sizeof(hdr));
c->utcp->send(c->utcp, &hdr, sizeof(hdr));
return true;
}
// delete connections that have been utcp_close()d.
if(c->state == CLOSED) {
if(c->reapable) {
- debug("Reaping %p\n", c);
+ debug(c, "reaping\n");
free_connection(c);
i--;
}
}
if(timerisset(&c->rtrx_timeout) && timercmp(&c->rtrx_timeout, &now, <)) {
- debug("retransmit()\n");
+ debug(c, "retransmitting after timeout\n");
retransmit(c);
}
projects / utcp / blobdiff