diff --git a/examples/http/xhttp.c b/examples/http/xhttp.c index c598210..eb315c6 100644 --- a/examples/http/xhttp.c +++ b/examples/http/xhttp.c @@ -1280,8 +1280,10 @@ static void when_data_is_ready_to_be_read(context_t *ctx, conn_t *conn) downloaded = b->used - before; } +#ifdef DEBUG fprintf(stderr, "XHTTP :: Downloaded %d bytes\n", downloaded); - +#endif + int served_during_this_while_loop = 0; while(1) diff --git a/makefile b/makefile index 5079721..b0b1a26 100644 --- a/makefile +++ b/makefile @@ -28,8 +28,8 @@ HFILES = $(wildcard $(SRCDIR)/*.h) OFILES = $(patsubst $(SRCDIR)/%.c, $(OBJDIR)/%.o, $(CFILES)) CFLAGS_WIN = -CFLAGS_LIN = -pthread -CFLAGS = -Wall -Wextra -g $(CFLAGS_$(OSTAG)) -DMICROTCP_DEBUG -DTCP_DEBUG +CFLAGS_LIN = -pthread -fsanitize=address,undefined +CFLAGS = -Wall -Wextra -g $(CFLAGS_$(OSTAG)) -DTCP_DEBUG #-DMICROTCP_DEBUG LIBFILE = $(OUTDIR)/libmicrotcp.a diff --git a/src/tcp.c b/src/tcp.c index 318eb02..2d7b53f 100644 --- a/src/tcp.c +++ b/src/tcp.c @@ -5,10 +5,30 @@ #include "tcp.h" #ifdef TCP_DEBUG -# include -# define TCP_DEBUG_LOG(fmt, ...) fprintf(stderr, "TCP :: " fmt "\n", ## __VA_ARGS__) +#include +#define TCP_DEBUG_LOG(fmt, ...) fprintf(stderr, "TCP :: " fmt "\n", ## __VA_ARGS__) #else -# define TCP_DEBUG_LOG(...) {} +#define TCP_DEBUG_LOG(...) {} +#endif + +#ifdef TCP_DEBUG +#define TCP_DEBUG_LOCATION_ARG(F, L) , const char *F, int L +#define TCP_DEBUG_LOCATION_PUT(F, L) , (F), (L) +#else +#define TCP_DEBUG_LOCATION_ARG(F, L) +#define TCP_DEBUG_LOCATION_PUT(F, L) +#endif + +#ifdef TCP_DEBUG +#define transmit(c, flags, no_payload) transmit_((c), (flags), (no_payload), __FILE__, __LINE__) +#else +#define transmit transmit_ +#endif + +#ifdef TCP_DEBUG +#define retransmit(c) retransmit_((c), __FILE__, __LINE__) +#else +#define retransmit retransmit_ #endif #define SLICE_EMPTY ((slice_t) {.ptr=NULL, .len=0}) @@ -87,6 +107,9 @@ connection_create(tcp_listener_t *listener, ip_address_t ip, uint16_t port, uint c->state = TCP_STATE_CLOSED; c->peer_port = port; c->peer_ip = ip; +#ifdef TCP_DEBUG + c->init_peer_seq = ack-1; +#endif c->retr_timer = NULL; c->wait_timer = NULL; c->rcv_unread = ack; @@ -123,13 +146,16 @@ static uint32_t choose_sequence_no(void) return 0; } -static void retransmit(tcp_connection_t *c); +static void retransmit_(tcp_connection_t *c TCP_DEBUG_LOCATION_ARG(file, line)); static void retr_timeout_callback(void *data) { tcp_connection_t *c = data; tcp_listener_t *l = c->listener; tcp_state_t *tcp = l->state; + assert(c->retr_timer); + TCP_DEBUG_LOG("Retransmission timer %ld triggered", c->retr_timer - tcp->timers.pool); + c->retr_timer = NULL; retransmit(c); @@ -243,9 +269,56 @@ transmit_bytes(tcp_state_t *tcp, ip_address_t ip, return tcp->callbacks.send(tcp->callbacks.data, ip, slices, COUNT(slices)); } -static int transmit_basic(tcp_state_t *tcp, transmit_config_t config) +#ifdef TCP_DEBUG +static void print_segment(uint64_t time_ms, tcp_segment_t header, slice_t payload, uint32_t init_peer_seq, bool recv, const char *file, int line) +{ + char flags[300]; + int flnum = 0; + if (header.flags & TCP_FLAG_FIN) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "FIN"); + } + if (header.flags & TCP_FLAG_SYN) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "SYN"); + } + if (header.flags & TCP_FLAG_RST) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "RST"); + } + if (header.flags & TCP_FLAG_PUSH) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "PUSH"); + } + if (header.flags & TCP_FLAG_ACK) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "ACK"); + } + if (header.flags & TCP_FLAG_URG) { + if (flnum > 0) flags[flnum++] = '|'; + flnum += snprintf(flags + flnum, sizeof(flags) - flnum, "URG"); + } + flags[flnum] = '\0'; + + TCP_DEBUG_LOG("%s %ld { %d -> %d | seq=%u, ack=%u, payload=%d, flags=%s } -- %s:%d", + recv ? "=>" : "<=", time_ms, + net_to_cpu_u16(header.src_port), + net_to_cpu_u16(header.dst_port), + net_to_cpu_u32(header.seq_no) - (recv ? init_peer_seq : 0), + net_to_cpu_u32(header.ack_no) - (recv ? 0 : init_peer_seq), + (int) payload.len, flags, + file, line); +} +#endif + +static int transmit_basic(tcp_state_t *tcp, transmit_config_t config, + uint32_t init_peer_seq + TCP_DEBUG_LOCATION_ARG(file, line)) { tcp_segment_t header = compile_segment(config); +#ifdef TCP_DEBUG + print_segment(tcp->timers.current_time_ms, header, config.payload, init_peer_seq, false, file, line); +#endif return transmit_bytes(tcp, config.peer, header, config.payload); } @@ -266,7 +339,7 @@ static void transmit_reply_rst(tcp_state_t *tcp, ip_address_t receiver, .window = 0, .payload = SLICE_EMPTY, }; - transmit_basic(tcp, config); + transmit_basic(tcp, config, 0 TCP_DEBUG_LOCATION_PUT(__FILE__, __LINE__)); } static void transmit_rst(tcp_connection_t *c, bool ack) @@ -290,38 +363,17 @@ static void transmit_rst(tcp_connection_t *c, bool ack) .window = c->rcv_wnd, .payload = SLICE_EMPTY, }; - transmit_basic(tcp, config); -} - + uint32_t init_peer_seq = 0; #ifdef TCP_DEBUG -#define TCP_DEBUG_LOCATION(F, L) , const char *F, int L -#else -#define TCP_DEBUG_LOCATION(F, L) + init_peer_seq = c->init_peer_seq; #endif - -static const char *flags_to_str(uint8_t flags) -{ - switch (flags) { - - case TCP_FLAG_ACK: return "ACK"; - case TCP_FLAG_FIN: return "FIN"; - case TCP_FLAG_SYN: return "SYN"; - case TCP_FLAG_RST: return "RST"; - case TCP_FLAG_URG: return "URG"; - - case TCP_FLAG_FIN | TCP_FLAG_ACK: return "FIN|ACK"; - case TCP_FLAG_SYN | TCP_FLAG_ACK: return "SYN|ACK"; - case TCP_FLAG_RST | TCP_FLAG_ACK: return "RST|ACK"; - - default: return "?"; - } - + transmit_basic(tcp, config, init_peer_seq TCP_DEBUG_LOCATION_PUT(__FILE__, __LINE__)); } static void transmit_(tcp_connection_t *c, uint8_t flags, bool no_payload - TCP_DEBUG_LOCATION(file, line)) + TCP_DEBUG_LOCATION_ARG(file, line)) { - TCP_DEBUG_LOG("transmit(flags=%s, no_payload=%s) at %s:%d", flags_to_str(flags), no_payload ? "true" : "false", file, line); + //TCP_DEBUG_LOG("transmit(flags=%s, no_payload=%s) at %s:%d", flags_to_str(flags), no_payload ? "true" : "false", file, line); tcp_listener_t *listener = c->listener; tcp_state_t *tcp = listener->state; @@ -383,7 +435,11 @@ static void transmit_(tcp_connection_t *c, uint8_t flags, bool no_payload .window = c->rcv_wnd, .payload = payload, }; - transmit_basic(tcp, config); + uint32_t init_peer_seq = 0; +#ifdef TCP_DEBUG + init_peer_seq = c->init_peer_seq; +#endif + transmit_basic(tcp, config, init_peer_seq TCP_DEBUG_LOCATION_PUT(file, line)); c->snd_nxt += payload.len; @@ -413,13 +469,7 @@ static void transmit_(tcp_connection_t *c, uint8_t flags, bool no_payload } } -#ifdef TCP_DEBUG -#define transmit(c, flags, no_payload) transmit_((c), (flags), (no_payload), __FILE__, __LINE__) -#else -#define transmit transmit_ -#endif - -static void retransmit(tcp_connection_t *c) +static void retransmit_(tcp_connection_t *c TCP_DEBUG_LOCATION_ARG(file, line)) { TCP_DEBUG_LOG("Retransmitting"); tcp_listener_t *listener = c->listener; @@ -427,8 +477,8 @@ static void retransmit(tcp_connection_t *c) size_t retr_queue_bytes = c->snd_nxt - c->snd_una; - //assert(retr_queue_bytes > 0); // If there were no bytes to ACK, - // there would be no active timer. + assert(retr_queue_bytes > 0); // If there were no bytes to ACK, + // there would be no active timer. size_t retr_queue_ghost = 0; if (c->waiting_ack_for_syn) retr_queue_ghost++; @@ -464,7 +514,11 @@ static void retransmit(tcp_connection_t *c) .window = c->rcv_wnd, .payload = payload, }; - transmit_basic(tcp, config); + uint32_t init_peer_seq = 0; +#ifdef TCP_DEBUG + init_peer_seq = c->init_peer_seq; +#endif + transmit_basic(tcp, config, init_peer_seq TCP_DEBUG_LOCATION_PUT(file, line)); } static void forget_acked(tcp_connection_t *c, uint32_t ack) @@ -815,7 +869,7 @@ state_listen(tcp_listener_t *listener, ip_address_t sender, transmit(c, TCP_FLAG_SYN | TCP_FLAG_ACK, true); c->state = TCP_STATE_SYN_RCVD; - + // Complete the processing in the SYN-RCVD state, but // don't repeat the SYN and ACK should not be repeated unset(seg, TCP_FLAG_SYN | TCP_FLAG_ACK); @@ -888,7 +942,7 @@ static void transition_to_time_wait(tcp_connection_t *c) c->retr_timer = NULL; } - size_t ms = 60; + size_t ms = 60; // FIXME: Should be in milliseconds c->wait_timer = tcp_timer_create(&tcp->timers, ms, "wait", wait_timeout_callback, c); if (c->wait_timer == NULL) { // Couldn't set the TIME-WAIT timer @@ -917,6 +971,10 @@ void tcp_process_segment(tcp_state_t *tcp, ip_address_t sender, // already established connections are ok but new ones are not so // the listener should be regarded as in the CLOSED state. +#ifdef TCP_DEBUG + print_segment(tcp->timers.current_time_ms, *segment, payload, c ? c->init_peer_seq : 0, true, __FILE__, __LINE__); +#endif + if (listener == NULL) connstate = TCP_STATE_CLOSED; // Not listening on destination port else { @@ -1263,7 +1321,6 @@ void tcp_process_segment(tcp_state_t *tcp, ip_address_t sender, // otherwise, ignore the segment. if (ack == c->snd_nxt) { - TCP_DEBUG_LOG("And here"); // Everything was ACKed, so if a FIN was sent that was ACKed too. transition_to_time_wait(c); } diff --git a/src/tcp.h b/src/tcp.h index 6aea7e9..31388dd 100644 --- a/src/tcp.h +++ b/src/tcp.h @@ -129,6 +129,10 @@ struct tcp_connection_t { tcp_timer_t *retr_timer; tcp_timer_t *wait_timer; +#ifdef TCP_DEBUG + uint32_t init_peer_seq; // First requence number of the peer, in cpu byte order +#endif + // Send Sequence Space // // 1 2 3 4 diff --git a/src/tcp_timer.c b/src/tcp_timer.c index 9869e7c..752708b 100644 --- a/src/tcp_timer.c +++ b/src/tcp_timer.c @@ -2,9 +2,16 @@ #include #include "tcp_timer.h" + +#ifdef TCP_DEBUG +#include +#define TCP_DEBUG_LOG(fmt, ...) fprintf(stderr, "TCP-TIMERS :: " fmt "\n", ## __VA_ARGS__) +#else +#define TCP_DEBUG_LOG(...) {} +#endif + void tcp_timerset_init(tcp_timerset_t *set) { - static_assert(TCP_MAX_TIMERS >= 0); if (TCP_MAX_TIMERS == 0) set->free_list = NULL; else { @@ -26,6 +33,8 @@ void tcp_timer_disable(tcp_timer_t *timer) { tcp_timerset_t *set = timer->set; + TCP_DEBUG_LOG("Timer %d disabled", (int) (timer - set->pool)); + // Pop the timer from the used list if (timer->prev) timer->prev->next = timer->next; @@ -46,12 +55,12 @@ tcp_timer_t *tcp_timer_create(tcp_timerset_t *set, size_t ms, { assert(callback); - if (set->free_list == NULL) + tcp_timer_t *timer = set->free_list; + if (timer == NULL) // Out of timers! This is really bad. // What can be done to mitigate this? return NULL; - tcp_timer_t *timer = set->free_list; set->free_list = timer->next; // NOTE: Since the free list is singly linked, there's // no need to change the prev member of the new @@ -78,6 +87,7 @@ tcp_timer_t *tcp_timer_create(tcp_timerset_t *set, size_t ms, timer->prev = NULL; timer->next = set->used_list; set->used_list->prev = timer; + set->used_list = timer; } else { // The timer isn't the first of the list. We need to // determine at which position it should be inserted @@ -95,11 +105,13 @@ tcp_timer_t *tcp_timer_create(tcp_timerset_t *set, size_t ms, // come after. Since we know the inserted item won't // be the first, then this one isn't the first element // of the list either, so its "prev" isn't NULL. + assert(cursor != set->used_list); assert(cursor->prev); timer->prev = cursor->prev; timer->next = cursor; cursor->prev->next = timer; cursor->prev = timer; + } else { // No element that needs to come after was found, // so its position should be the last. @@ -108,6 +120,7 @@ tcp_timer_t *tcp_timer_create(tcp_timerset_t *set, size_t ms, timer->next = NULL; } } + TCP_DEBUG_LOG("Timer %d created (%s)", (int) (timer - set->pool), name); return timer; } @@ -131,7 +144,8 @@ void tcp_timerset_step(tcp_timerset_t *set, size_t ms) // timed out timeout was the previous one. break; - // Trigger the callback + TCP_DEBUG_LOG("Timer %d triggered (deadline %d, current %d, set_time=%d, trg_time=%d)", (int) (timeout - set->pool), (int) timeout->deadline, (int) set->current_time_ms, (int) timeout->set_time, (int) timeout->trg_time); + timeout->callback(timeout->data); timedout_tail = timeout;