From 0cc06a5993afcce6d524a08537691f86c8ad9f48 Mon Sep 17 00:00:00 2001 From: Simon Brummer Date: Fri, 9 Oct 2020 11:14:42 +0200 Subject: [PATCH] gnrc_tcp: Overhaul all debug messages --- sys/net/gnrc/transport_layer/tcp/gnrc_tcp.c | 150 +++++++++++++++--- .../transport_layer/tcp/gnrc_tcp_eventloop.c | 77 ++++++--- .../gnrc/transport_layer/tcp/gnrc_tcp_fsm.c | 98 +++++++++--- .../transport_layer/tcp/gnrc_tcp_option.c | 21 +-- .../gnrc/transport_layer/tcp/gnrc_tcp_pkt.c | 70 +++++--- .../transport_layer/tcp/gnrc_tcp_rcvbuf.c | 17 +- .../transport_layer/tcp/internal/common.h | 32 ++++ tests/gnrc_tcp/tests/05-garbage-pkts.py | 13 +- 8 files changed, 373 insertions(+), 105 deletions(-) diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp.c index d03057a04cc7..575192e82d4b 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp.c @@ -52,20 +52,26 @@ static evtimer_t _tcp_mbox_timer; static void _sched_mbox(evtimer_mbox_event_t *event, uint32_t offset, uint16_t type, mbox_t *mbox) { + TCP_DEBUG_ENTER; event->event.offset = offset; event->msg.type = type; evtimer_add_mbox(&_tcp_mbox_timer, event, mbox); + TCP_DEBUG_LEAVE; } static void _sched_connection_timeout(evtimer_mbox_event_t *event, mbox_t *mbox) { + TCP_DEBUG_ENTER; _sched_mbox(event, CONFIG_GNRC_TCP_CONNECTION_TIMEOUT_DURATION_MS, MSG_TYPE_CONNECTION_TIMEOUT, mbox); + TCP_DEBUG_LEAVE; } static void _unsched_mbox(evtimer_mbox_event_t *event) { + TCP_DEBUG_ENTER; evtimer_del(&_tcp_mbox_timer, (evtimer_event_t *)event); + TCP_DEBUG_LEAVE; } /** @@ -88,6 +94,7 @@ static void _unsched_mbox(evtimer_mbox_event_t *event) static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, const uint8_t *local_addr, uint16_t local_port, int passive) { + TCP_DEBUG_ENTER; msg_t msg; msg_t msg_queue[TCP_MSG_QUEUE_SIZE]; mbox_t mbox = MBOX_INIT(msg_queue, TCP_MSG_QUEUE_SIZE); @@ -99,6 +106,8 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, /* TCB is already connected: Return -EISCONN */ if (tcb->state != FSM_STATE_CLOSED) { mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_ERROR("-EISCONN: TCB already connected."); + TCP_DEBUG_LEAVE; return -EISCONN; } @@ -114,7 +123,8 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, if (local_addr && tcb->address_family == AF_INET6) { /* Store given address in TCB */ if (memcpy(tcb->local_addr, local_addr, sizeof(tcb->local_addr)) == NULL) { - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : Invalid peer addr\n"); + TCP_DEBUG_ERROR("-EINVAL: Invalid peer address."); + TCP_DEBUG_LEAVE; return -EINVAL; } @@ -140,7 +150,8 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, /* Store Address information in TCB */ if (memcpy(tcb->peer_addr, remote->addr.ipv6, sizeof(tcb->peer_addr)) == NULL) { - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : Invalid peer addr\n"); + TCP_DEBUG_ERROR("-EINVAL: Invalid peer address."); + TCP_DEBUG_LEAVE; return -EINVAL; } tcb->ll_iface = remote->netif; @@ -158,10 +169,10 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, /* Call FSM with event: CALL_OPEN */ ret = _fsm(tcb, FSM_EVENT_CALL_OPEN, NULL, NULL, 0); if (ret == -ENOMEM) { - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : Out of receive buffers.\n"); + TCP_DEBUG_ERROR("-ENOMEM: All receive buffers are in use."); } else if (ret == -EADDRINUSE) { - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : local_port is already in use.\n"); + TCP_DEBUG_ERROR("-EADDRINUSE: local_port is already in use."); } /* Wait until a connection was established or closed */ @@ -170,7 +181,7 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, mbox_get(&mbox, &msg); switch (msg.type) { case MSG_TYPE_NOTIFY_USER: - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : MSG_TYPE_NOTIFY_USER\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_NOTIFY_USER."); /* Setup a timeout to be able to revert back to LISTEN state, in case the * send SYN+ACK we received upon entering SYN_RCVD is never acknowledged @@ -182,7 +193,7 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, break; case MSG_TYPE_CONNECTION_TIMEOUT: - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : CONNECTION_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_CONNECTION_TIMEOUT."); /* The connection establishment attempt timed out: * 1) Active connections return -ETIMEOUT. @@ -194,12 +205,13 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, } else { _fsm(tcb, FSM_EVENT_TIMEOUT_CONNECTION, NULL, NULL, 0); + TCP_DEBUG_ERROR("-ETIMEDOUT: Connection timed out."); ret = -ETIMEDOUT; } break; default: - DEBUG("gnrc_tcp.c : _gnrc_tcp_open() : other message type\n"); + TCP_DEBUG_ERROR("Received unexpected message."); } } @@ -207,9 +219,11 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, _fsm_set_mbox(tcb, NULL); _unsched_mbox(&tcb->event_misc); if (tcb->state == FSM_STATE_CLOSED && ret == 0) { + TCP_DEBUG_ERROR("-ECONNREFUSED: Connection refused by peer."); ret = -ECONNREFUSED; } mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return ret; } @@ -217,8 +231,11 @@ static int _gnrc_tcp_open(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, int gnrc_tcp_ep_init(gnrc_tcp_ep_t *ep, int family, const uint8_t *addr, size_t addr_size, uint16_t port, uint16_t netif) { + TCP_DEBUG_ENTER; #ifdef MODULE_GNRC_IPV6 if (family != AF_INET6) { + TCP_DEBUG_ERROR("-EAFNOSUPPORT: Parameter family is not AF_INET6.") + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; } @@ -229,23 +246,29 @@ int gnrc_tcp_ep_init(gnrc_tcp_ep_t *ep, int family, const uint8_t *addr, size_t memcpy(ep->addr.ipv6, addr, sizeof(ipv6_addr_t)); } else { + TCP_DEBUG_ERROR("-EINVAL: Parameter addr is invalid.") + TCP_DEBUG_LEAVE; return -EINVAL; } #else /* Suppress Compiler Warnings */ (void) addr; (void) addr_size; + TCP_DEBUG_ERROR("-EAFNOSUPPORT: No network layer configured.") + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; #endif ep->family = family; ep->port = port; ep->netif = netif; + TCP_DEBUG_LEAVE; return 0; } int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) { + TCP_DEBUG_ENTER; assert(str); unsigned port = 0; @@ -257,10 +280,14 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) /* 1) Ensure that str contains a single pair of brackets */ if (!addr_begin || !addr_end || strchr(addr_begin + 1, '[') || strchr(addr_end + 1, ']')) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* 2) Ensure that the first character is the opening bracket */ else if (addr_begin != str) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } @@ -269,12 +296,16 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) if (port_begin) { /* 3.1) Ensure that there are characters left to parse after ':'. */ if (*(++port_begin) == '\0') { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* 3.2) Ensure that port is a number (atol, does not report errors) */ for (char *ptr = port_begin; *ptr; ++ptr) { if ((*ptr < '0') || ('9' < *ptr)) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } } @@ -282,6 +313,8 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) /* 3.3) Read and verify that given number port is within range */ port = atol(port_begin); if (port > 0xFFFF) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } } @@ -291,12 +324,16 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) if (if_begin) { /* 4.1) Ensure that the identifier is not empty and within brackets. */ if (addr_end <= (++if_begin)) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* 4.2) Ensure that the identifier is a number (atol, does not report errors) */ for (char *ptr = if_begin; ptr != addr_end; ++ptr) { if ((*ptr < '0') || ('9' < *ptr)) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } } @@ -320,11 +357,15 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) tmp[len] = '\0'; } else { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* 5.2) Try to read address into endpoint. */ if (ipv6_addr_from_str((ipv6_addr_t *) ep->addr.ipv6, tmp) == NULL) { + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; } ep->family = AF_INET6; @@ -332,16 +373,20 @@ int gnrc_tcp_ep_from_str(gnrc_tcp_ep_t *ep, const char *str) /* Suppress Compiler Warnings */ (void) port; (void) netif; + TCP_DEBUG_ERROR("-EINVAL: Invalid address string."); + TCP_DEBUG_LEAVE; return -EINVAL; #endif ep->port = (uint16_t) port; ep->netif = (uint16_t) netif; + TCP_DEBUG_LEAVE; return 0; } int gnrc_tcp_init(void) { + TCP_DEBUG_ENTER; /* Initialize TCB list */ _rcvbuf_init(); @@ -349,26 +394,31 @@ int gnrc_tcp_init(void) evtimer_init_mbox(&_tcp_mbox_timer); /* Start TCP processing thread */ - return _gnrc_tcp_event_loop_init(); + kernel_pid_t pid = _gnrc_tcp_event_loop_init(); + TCP_DEBUG_LEAVE; + return pid; } void gnrc_tcp_tcb_init(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; memset(tcb, 0, sizeof(gnrc_tcp_tcb_t)); #ifdef MODULE_GNRC_IPV6 tcb->address_family = AF_INET6; #else - DEBUG("gnrc_tcp.c : gnrc_tcp_tcb_init() : Address unspec, add netlayer module to makefile\n"); + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); #endif tcb->rtt_var = RTO_UNINITIALIZED; tcb->srtt = RTO_UNINITIALIZED; tcb->rto = RTO_UNINITIALIZED; mutex_init(&(tcb->fsm_lock)); mutex_init(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; } int gnrc_tcp_open_active(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, uint16_t local_port) { + TCP_DEBUG_ENTER; assert(tcb != NULL); assert(remote != NULL); assert(remote->port != PORT_UNSPEC); @@ -376,23 +426,32 @@ int gnrc_tcp_open_active(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *remote, uint1 /* Check if given AF-Family in remote is supported */ #ifdef MODULE_GNRC_IPV6 if (remote->family != AF_INET6) { + TCP_DEBUG_ERROR("-EAFNOSUPPORT: remote AF-Family not supported."); + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; } #else + TCP_DEBUG_ERROR("-EAFNOSUPPORT: AF-Family not supported."); + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; #endif /* Check if AF-Family for target address matches internally used AF-Family */ if (remote->family != tcb->address_family) { + TCP_DEBUG_ERROR("-EINVAL: local and remote AF-Family don't match."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* Proceed with connection opening */ - return _gnrc_tcp_open(tcb, remote, NULL, local_port, 0); + int res = _gnrc_tcp_open(tcb, remote, NULL, local_port, 0); + TCP_DEBUG_LEAVE; + return res; } int gnrc_tcp_open_passive(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *local) { + TCP_DEBUG_ENTER; assert(tcb != NULL); assert(local != NULL); assert(local->port != PORT_UNSPEC); @@ -400,17 +459,25 @@ int gnrc_tcp_open_passive(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *local) /* Check if given AF-Family in local is supported */ #ifdef MODULE_GNRC_IPV6 if (local->family != AF_INET6) { + TCP_DEBUG_ERROR("-EAFNOSUPPORT: AF-Family not supported."); + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; } /* Check if AF-Family matches internally used AF-Family */ if (local->family != tcb->address_family) { + TCP_DEBUG_ERROR("-EINVAL: AF-Family doesn't match."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* Proceed with connection opening */ - return _gnrc_tcp_open(tcb, NULL, local->addr.ipv6, local->port, 1); + int res = _gnrc_tcp_open(tcb, NULL, local->addr.ipv6, local->port, 1); + TCP_DEBUG_LEAVE; + return res; #else + TCP_DEBUG_ERROR("-EAFNOSUPPORT: AF-Family not supported."); + TCP_DEBUG_LEAVE; return -EAFNOSUPPORT; #endif } @@ -418,6 +485,7 @@ int gnrc_tcp_open_passive(gnrc_tcp_tcb_t *tcb, const gnrc_tcp_ep_t *local) ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, const uint32_t timeout_duration_ms) { + TCP_DEBUG_ENTER; assert(tcb != NULL); assert(data != NULL); @@ -436,6 +504,8 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, /* Check if connection is in a valid state */ if (tcb->state != FSM_STATE_ESTABLISHED && tcb->state != FSM_STATE_CLOSE_WAIT) { mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_ERROR("-ENOTCONN: TCB is not connected."); + TCP_DEBUG_LEAVE; return -ENOTCONN; } @@ -454,6 +524,7 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, while (ret == 0 || tcb->pkt_retransmit != NULL) { /* Check if the connections state is closed. If so, a reset was received */ if (tcb->state == FSM_STATE_CLOSED) { + TCP_DEBUG_ERROR("-ECONNRESET: Connection was reset by peer."); ret = -ECONNRESET; break; } @@ -480,19 +551,21 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, mbox_get(&mbox, &msg); switch (msg.type) { case MSG_TYPE_CONNECTION_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_send() : CONNECTION_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_CONNECTION_TIMEOUT."); _fsm(tcb, FSM_EVENT_TIMEOUT_CONNECTION, NULL, NULL, 0); + TCP_DEBUG_ERROR("-ECONNABORTED: Connection timed out."); ret = -ECONNABORTED; break; case MSG_TYPE_USER_SPEC_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_send() : USER_SPEC_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_USER_SPEC_TIMEOUT."); _fsm(tcb, FSM_EVENT_CLEAR_RETRANSMIT, NULL, NULL, 0); + TCP_DEBUG_ERROR("-ETIMEDOUT: User specified timeout expired."); ret = -ETIMEDOUT; break; case MSG_TYPE_PROBE_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_send() : PROBE_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_PROBE_TIMEOUT."); /* Send probe */ _fsm(tcb, FSM_EVENT_SEND_PROBE, NULL, NULL, 0); probe_timeout_duration_ms += probe_timeout_duration_ms; @@ -507,7 +580,7 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, break; case MSG_TYPE_NOTIFY_USER: - DEBUG("gnrc_tcp.c : gnrc_tcp_send() : NOTIFY_USER\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_NOTIFY_USER."); /* Connection is alive: Reset Connection Timeout */ _unsched_mbox(&tcb->event_misc); @@ -521,7 +594,7 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, break; default: - DEBUG("gnrc_tcp.c : gnrc_tcp_send() : other message type\n"); + TCP_DEBUG_ERROR("Received unexpected message."); } } @@ -531,12 +604,14 @@ ssize_t gnrc_tcp_send(gnrc_tcp_tcb_t *tcb, const void *data, const size_t len, _unsched_mbox(&event_probe_timeout); _unsched_mbox(&event_user_timeout); mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return ret; } ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, const uint32_t timeout_duration_ms) { + TCP_DEBUG_ENTER; assert(tcb != NULL); assert(data != NULL); @@ -553,6 +628,8 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, if (tcb->state != FSM_STATE_ESTABLISHED && tcb->state != FSM_STATE_FIN_WAIT_1 && tcb->state != FSM_STATE_FIN_WAIT_2 && tcb->state != FSM_STATE_CLOSE_WAIT) { mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_ERROR("-ENOTCONN: TCB is not connected."); + TCP_DEBUG_LEAVE; return -ENOTCONN; } @@ -561,6 +638,7 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, if (tcb->state == FSM_STATE_CLOSE_WAIT) { ret = _fsm(tcb, FSM_EVENT_CALL_RECV, NULL, data, max_len); mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return ret; } @@ -568,9 +646,11 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, if (timeout_duration_ms == 0) { ret = _fsm(tcb, FSM_EVENT_CALL_RECV, NULL, data, max_len); if (ret == 0) { + TCP_DEBUG_ERROR("-EAGAIN: Not data available, try later again."); ret = -EAGAIN; } mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return ret; } @@ -589,6 +669,7 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, while (ret == 0) { /* Check if the connections state is closed. If so, a reset was received */ if (tcb->state == FSM_STATE_CLOSED) { + TCP_DEBUG_ERROR("-ECONNRESET: Connection was reset by peer."); ret = -ECONNRESET; break; } @@ -606,23 +687,25 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, mbox_get(&mbox, &msg); switch (msg.type) { case MSG_TYPE_CONNECTION_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_recv() : CONNECTION_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_CONNECTION_TIMEOUT."); _fsm(tcb, FSM_EVENT_TIMEOUT_CONNECTION, NULL, NULL, 0); + TCP_DEBUG_ERROR("-ECONNABORTED: Connection timed out."); ret = -ECONNABORTED; break; case MSG_TYPE_USER_SPEC_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_recv() : USER_SPEC_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_USER_SPEC_TIMEOUT."); _fsm(tcb, FSM_EVENT_CLEAR_RETRANSMIT, NULL, NULL, 0); + TCP_DEBUG_ERROR("-ETIMEDOUT: User specified timeout expired."); ret = -ETIMEDOUT; break; case MSG_TYPE_NOTIFY_USER: - DEBUG("gnrc_tcp.c : gnrc_tcp_recv() : NOTIFY_USER\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_NOTIFY_USER."); break; default: - DEBUG("gnrc_tcp.c : gnrc_tcp_recv() : other message type\n"); + TCP_DEBUG_ERROR("Received unexpected message."); } } } @@ -632,11 +715,13 @@ ssize_t gnrc_tcp_recv(gnrc_tcp_tcb_t *tcb, void *data, const size_t max_len, _unsched_mbox(&tcb->event_misc); _unsched_mbox(&event_user_timeout); mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return ret; } void gnrc_tcp_close(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; assert(tcb != NULL); msg_t msg; @@ -649,6 +734,7 @@ void gnrc_tcp_close(gnrc_tcp_tcb_t *tcb) /* Return if connection is closed */ if (tcb->state == FSM_STATE_CLOSED) { mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; return; } @@ -666,16 +752,16 @@ void gnrc_tcp_close(gnrc_tcp_tcb_t *tcb) mbox_get(&mbox, &msg); switch (msg.type) { case MSG_TYPE_CONNECTION_TIMEOUT: - DEBUG("gnrc_tcp.c : gnrc_tcp_close() : CONNECTION_TIMEOUT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_CONNECTION_TIMEOUT."); _fsm(tcb, FSM_EVENT_TIMEOUT_CONNECTION, NULL, NULL, 0); break; case MSG_TYPE_NOTIFY_USER: - DEBUG("gnrc_tcp.c : gnrc_tcp_close() : NOTIFY_USER\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_NOTIFY_USER."); break; default: - DEBUG("gnrc_tcp.c : gnrc_tcp_close() : other message type\n"); + TCP_DEBUG_ERROR("Received unexpected message."); } } @@ -683,10 +769,12 @@ void gnrc_tcp_close(gnrc_tcp_tcb_t *tcb) _fsm_set_mbox(tcb, NULL); _unsched_mbox(&tcb->event_misc); mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; } void gnrc_tcp_abort(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; assert(tcb != NULL); /* Lock the TCB for this function call */ @@ -696,36 +784,48 @@ void gnrc_tcp_abort(gnrc_tcp_tcb_t *tcb) _fsm(tcb, FSM_EVENT_CALL_ABORT, NULL, NULL, 0); } mutex_unlock(&(tcb->function_lock)); + TCP_DEBUG_LEAVE; } int gnrc_tcp_calc_csum(const gnrc_pktsnip_t *hdr, const gnrc_pktsnip_t *pseudo_hdr) { + TCP_DEBUG_ENTER; uint16_t csum; if ((hdr == NULL) || (pseudo_hdr == NULL)) { + TCP_DEBUG_ERROR("-EFAULT: hdr or pseudo_hdr is NULL."); + TCP_DEBUG_LEAVE; return -EFAULT; } if (hdr->type != GNRC_NETTYPE_TCP) { + TCP_DEBUG_ERROR("-EBADMSG: Variable hdr is no TCP header."); + TCP_DEBUG_LEAVE; return -EBADMSG; } csum = _pkt_calc_csum(hdr, pseudo_hdr, hdr->next); if (csum == 0) { + TCP_DEBUG_ERROR("-ENOENT"); + TCP_DEBUG_LEAVE; return -ENOENT; } ((tcp_hdr_t *)hdr->data)->checksum = byteorder_htons(csum); + + TCP_DEBUG_LEAVE; return 0; } gnrc_pktsnip_t *gnrc_tcp_hdr_build(gnrc_pktsnip_t *payload, uint16_t src, uint16_t dst) { + TCP_DEBUG_ENTER; gnrc_pktsnip_t *res; tcp_hdr_t *hdr; /* Allocate header */ res = gnrc_pktbuf_add(payload, NULL, sizeof(tcp_hdr_t), GNRC_NETTYPE_TCP); if (res == NULL) { - DEBUG("gnrc_tcp.c : gnrc_tcp_hdr_build() : No space left in packet buffer\n"); + TCP_DEBUG_ERROR("pktbuf is full."); + TCP_DEBUG_LEAVE; return NULL; } hdr = (tcp_hdr_t *) res->data; @@ -738,5 +838,7 @@ gnrc_pktsnip_t *gnrc_tcp_hdr_build(gnrc_pktsnip_t *payload, uint16_t src, uint16 hdr->dst_port = byteorder_htons(dst); hdr->checksum = byteorder_htons(0); hdr->off_ctl = byteorder_htons(TCP_HDR_OFFSET_MIN); + + TCP_DEBUG_LEAVE; return res; } diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_eventloop.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_eventloop.c index 45fa2f33e2f6..556015e77139 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_eventloop.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_eventloop.c @@ -60,15 +60,19 @@ static kernel_pid_t _tcp_eventloop_pid = KERNEL_PID_UNDEF; void _gnrc_tcp_event_loop_sched(evtimer_msg_event_t *event, uint32_t offset, uint16_t type, void *context) { + TCP_DEBUG_ENTER; event->event.offset = offset; event->msg.type = type; event->msg.content.ptr = context; evtimer_add_msg(&_tcp_msg_timer, event, _tcp_eventloop_pid); + TCP_DEBUG_LEAVE; } void _gnrc_tcp_event_loop_unsched(evtimer_msg_event_t *event) { + TCP_DEBUG_ENTER; evtimer_del(&_tcp_msg_timer, (evtimer_event_t *)event); + TCP_DEBUG_LEAVE; } /** @@ -78,10 +82,11 @@ void _gnrc_tcp_event_loop_unsched(evtimer_msg_event_t *event) * * @returns Zero on success. * Negative value on error. - * @returns -EBADMSG if TCP header is missing in @p pkt. + * @returns -EBADMSG if required header is missing in @p pkt. */ static int _send(gnrc_pktsnip_t *pkt) { + TCP_DEBUG_ENTER; assert(pkt != NULL); /* NOTE: In sending direction: pkt = nw, nw->next = tcp, tcp->next = payload */ @@ -90,8 +95,9 @@ static int _send(gnrc_pktsnip_t *pkt) gnrc_pktsnip_t *nw = NULL; if (tcp == NULL) { - DEBUG("gnrc_tcp_eventloop : _send() : tcp header missing.\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-EBADMSG: Packet contains no TCP header."); + TCP_DEBUG_LEAVE; return -EBADMSG; } @@ -100,18 +106,19 @@ static int _send(gnrc_pktsnip_t *pkt) /* Get IPv6 header, discard packet if doesn't contain an ipv6 header */ nw = gnrc_pktsnip_search_type(pkt, GNRC_NETTYPE_IPV6); if (nw == NULL) { - DEBUG("gnrc_tcp_eventloop.c : _send() : pkt contains no ipv6 layer header\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-EBADMSG: Packet contains no IPv6 header."); + TCP_DEBUG_LEAVE; return -EBADMSG; } #endif - /* Dispatch packet to network layer */ assert(nw != NULL); if (!gnrc_netapi_dispatch_send(nw->type, GNRC_NETREG_DEMUX_CTX_ALL, pkt)) { - DEBUG("gnrc_tcp_eventloop : _send() : network layer not found\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("Can't dispatch to network layer."); } + TCP_DEBUG_LEAVE; return 0; } @@ -122,6 +129,7 @@ static int _send(gnrc_pktsnip_t *pkt) * * @returns Zero on success. * Negative value on error. + * -EBADMSG if required header is missing or invalid in @p pkt. * -EACCES if write access to packet was not acquired. * -ERANGE if segment offset value is less than 5. * -ENOMSG if packet couldn't be marked. @@ -130,6 +138,7 @@ static int _send(gnrc_pktsnip_t *pkt) */ static int _receive(gnrc_pktsnip_t *pkt) { + TCP_DEBUG_ENTER; /* NOTE: In receiving direction: pkt = payload, payload->next = tcp, tcp->next = nw */ uint16_t ctl = 0; uint16_t src = 0; @@ -144,8 +153,9 @@ static int _receive(gnrc_pktsnip_t *pkt) /* Get write access to the TCP header */ gnrc_pktsnip_t *tcp = gnrc_pktbuf_start_write(pkt); if (tcp == NULL) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : can't write to packet\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-EACCESS: Can't write to packet."); + TCP_DEBUG_LEAVE; return -EACCES; } pkt = tcp; @@ -154,24 +164,27 @@ static int _receive(gnrc_pktsnip_t *pkt) /* Get IPv6 header, discard packet if doesn't contain an ip header */ ip = gnrc_pktsnip_search_type(pkt, GNRC_NETTYPE_IPV6); if (ip == NULL) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : pkt contains no IP Header\n"); gnrc_pktbuf_release(pkt); - return 0; + TCP_DEBUG_ERROR("-EBADMSG: Packet contains no IPv6 header."); + TCP_DEBUG_LEAVE; + return -EBADMSG; } #endif /* Get TCP header */ tcp = gnrc_pktsnip_search_type(pkt, GNRC_NETTYPE_TCP); if (tcp == NULL) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : pkt contains no TCP Header\n"); gnrc_pktbuf_release(pkt); - return 0; + TCP_DEBUG_ERROR("-EBADMSG: Packet contains no TCP header."); + TCP_DEBUG_LEAVE; + return -EBADMSG; } if (tcp->size < sizeof(tcp_hdr_t)) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : packet is too short\n"); gnrc_pktbuf_release(pkt); - return -ERANGE; + TCP_DEBUG_ERROR("-EBADMSG: Packet size less than minimal header size."); + TCP_DEBUG_LEAVE; + return -EBADMSG; } /* Extract control bits, src and dst ports and check if SYN is set (not SYN+ACK) */ @@ -183,8 +196,9 @@ static int _receive(gnrc_pktsnip_t *pkt) /* Validate offset */ if (GET_OFFSET(ctl) < TCP_HDR_OFFSET_MIN) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : unexpected Offset Value\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-ERANGE: Invalid TCP header offset."); + TCP_DEBUG_LEAVE; return -ERANGE; } @@ -195,8 +209,9 @@ static int _receive(gnrc_pktsnip_t *pkt) if ((pkt->type == GNRC_NETTYPE_TCP) && (pkt->size != hdr_size)) { tcp = gnrc_pktbuf_mark(pkt, hdr_size, GNRC_NETTYPE_TCP); if (tcp == NULL) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : Header marking failed\n"); gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-ENOMSG: Header marking failed."); + TCP_DEBUG_LEAVE; return -ENOMSG; } pkt->type = GNRC_NETTYPE_UNDEF; @@ -205,9 +220,10 @@ static int _receive(gnrc_pktsnip_t *pkt) /* Validate checksum */ if (byteorder_ntohs(hdr->checksum) != _pkt_calc_csum(tcp, ip, pkt)) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : Invalid checksum\n"); #ifndef MODULE_FUZZING gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-EINVAL: Invalid checksum."); + TCP_DEBUG_LEAVE; return -EINVAL; #endif } @@ -242,6 +258,7 @@ static int _receive(gnrc_pktsnip_t *pkt) } #else /* Suppress compiler warnings if TCP is built without network layer */ + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); (void) syn; (void) src; (void) dst; @@ -259,23 +276,26 @@ static int _receive(gnrc_pktsnip_t *pkt) } /* No fitting TCB has been found. Respond with reset */ else { - DEBUG("gnrc_tcp_eventloop.c : _receive() : Can't find fitting tcb\n"); if ((ctl & MSK_RST) != MSK_RST) { _pkt_build_reset_from_pkt(&reset, pkt); if (gnrc_netapi_send(_tcp_eventloop_pid, reset) < 1) { - DEBUG("gnrc_tcp_eventloop.c : _receive() : unable to send reset packet\n"); gnrc_pktbuf_release(reset); + TCP_DEBUG_ERROR("Can't dispatch to network layer."); } } gnrc_pktbuf_release(pkt); + TCP_DEBUG_ERROR("-ENOTCONN: Unable to find matching TCB."); + TCP_DEBUG_LEAVE; return -ENOTCONN; } gnrc_pktbuf_release(pkt); + TCP_DEBUG_LEAVE; return 0; } static void *_event_loop(__attribute__((unused)) void *arg) { + TCP_DEBUG_ENTER; msg_t msg; msg_t reply; @@ -300,13 +320,13 @@ static void *_event_loop(__attribute__((unused)) void *arg) switch (msg.type) { /* Pass message up the network stack */ case GNRC_NETAPI_MSG_TYPE_RCV: - DEBUG("gnrc_tcp_eventloop.c : _event_loop() : GNRC_NETAPI_MSG_TYPE_RCV\n"); + TCP_DEBUG_INFO("Received GNRC_NETAPI_MSG_TYPE_RCV."); _receive((gnrc_pktsnip_t *)msg.content.ptr); break; /* Pass message down the network stack */ case GNRC_NETAPI_MSG_TYPE_SND: - DEBUG("gnrc_tcp_eventloop.c : _event_loop() : GNRC_NETAPI_MSG_TYPE_SND\n"); + TCP_DEBUG_INFO("Received GNRC_NETAPI_MSG_TYPE_SND."); _send((gnrc_pktsnip_t *)msg.content.ptr); break; @@ -318,37 +338,44 @@ static void *_event_loop(__attribute__((unused)) void *arg) /* Retransmission timer expired: Call FSM with retransmission event */ case MSG_TYPE_RETRANSMISSION: - DEBUG("gnrc_tcp_eventloop.c : _event_loop() : MSG_TYPE_RETRANSMISSION\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_RETRANSMISSION."); _fsm((gnrc_tcp_tcb_t *)msg.content.ptr, FSM_EVENT_TIMEOUT_RETRANSMIT, NULL, NULL, 0); break; /* Timewait timer expired: Call FSM with timewait event */ case MSG_TYPE_TIMEWAIT: - DEBUG("gnrc_tcp_eventloop.c : _event_loop() : MSG_TYPE_TIMEWAIT\n"); + TCP_DEBUG_INFO("Received MSG_TYPE_TIMEWAIT."); _fsm((gnrc_tcp_tcb_t *)msg.content.ptr, FSM_EVENT_TIMEOUT_TIMEWAIT, NULL, NULL, 0); break; default: - DEBUG("gnrc_tcp_eventloop.c : _event_loop() : received expected message\n"); + TCP_DEBUG_ERROR("Received unexpected message."); } } /* Never reached */ + TCP_DEBUG_ERROR("This function should never exit."); + TCP_DEBUG_LEAVE; return NULL; } int _gnrc_tcp_event_loop_init(void) { + TCP_DEBUG_ENTER; /* Guard: Check if thread is already running */ if (_tcp_eventloop_pid != KERNEL_PID_UNDEF) { + TCP_DEBUG_ERROR("-EEXIST: TCP eventloop already running."); + TCP_DEBUG_LEAVE; return -EEXIST; } /* Initialize timers */ evtimer_init_msg(&_tcp_msg_timer); - return thread_create(_stack, sizeof(_stack), TCP_EVENTLOOP_PRIO, - THREAD_CREATE_STACKTEST, _event_loop, NULL, - "gnrc_tcp"); + kernel_pid_t pid = thread_create(_stack, sizeof(_stack), TCP_EVENTLOOP_PRIO, + THREAD_CREATE_STACKTEST, _event_loop, NULL, + "gnrc_tcp"); + TCP_DEBUG_LEAVE; + return pid; } diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_fsm.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_fsm.c index 14afea89498a..ca0d4b2e41d5 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_fsm.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_fsm.c @@ -55,9 +55,11 @@ */ static int _is_local_port_in_use(const uint16_t port_number) { + TCP_DEBUG_ENTER; gnrc_tcp_tcb_t *iter = NULL; tcb_list_t *list = _gnrc_tcp_common_get_tcb_list(); LL_SEARCH_SCALAR(list->head, iter, local_port, port_number); + TCP_DEBUG_LEAVE; return (iter != NULL); } @@ -68,6 +70,7 @@ static int _is_local_port_in_use(const uint16_t port_number) */ static uint16_t _get_random_local_port(void) { + TCP_DEBUG_ENTER; uint16_t ret = 0; do { ret = random_uint32(); @@ -75,6 +78,7 @@ static uint16_t _get_random_local_port(void) continue; } } while(_is_local_port_in_use(ret)); + TCP_DEBUG_LEAVE; return ret; } @@ -87,11 +91,13 @@ static uint16_t _get_random_local_port(void) */ static int _clear_retransmit(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; if (tcb->pkt_retransmit != NULL) { _gnrc_tcp_event_loop_unsched(&tcb->event_retransmit); gnrc_pktbuf_release(tcb->pkt_retransmit); tcb->pkt_retransmit = NULL; } + TCP_DEBUG_LEAVE; return 0; } @@ -104,9 +110,11 @@ static int _clear_retransmit(gnrc_tcp_tcb_t *tcb) */ static int _restart_timewait_timer(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; _gnrc_tcp_event_loop_unsched(&tcb->event_retransmit); _gnrc_tcp_event_loop_sched(&tcb->event_retransmit, 2 * CONFIG_GNRC_TCP_MSL_MS, MSG_TYPE_TIMEWAIT, tcb); + TCP_DEBUG_LEAVE; return 0; } @@ -122,8 +130,7 @@ static int _restart_timewait_timer(gnrc_tcp_tcb_t *tcb) */ static int _transition_to(gnrc_tcp_tcb_t *tcb, fsm_state_t state) { - DEBUG("_transition_to: %d\n", state); - + TCP_DEBUG_ENTER; gnrc_tcp_tcb_t *iter = NULL; tcb_list_t *list = _gnrc_tcp_common_get_tcb_list(); @@ -174,6 +181,8 @@ static int _transition_to(gnrc_tcp_tcb_t *tcb, fsm_state_t state) /* Check if given port number is in use: return error */ if (_is_local_port_in_use(tcb->local_port)) { mutex_unlock(&list->lock); + TCP_DEBUG_ERROR("-EADDRINUSE: Port already used.") + TCP_DEBUG_LEAVE; return -EADDRINUSE; } } @@ -200,6 +209,7 @@ static int _transition_to(gnrc_tcp_tcb_t *tcb, fsm_state_t state) break; } tcb->state = state; + TCP_DEBUG_LEAVE; return 0; } @@ -214,12 +224,13 @@ static int _transition_to(gnrc_tcp_tcb_t *tcb, fsm_state_t state) */ static int _fsm_call_open(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; int ret = 0; - DEBUG("gnrc_tcp_fsm.c : _fsm_call_open()\n"); - /* Allocate receive buffer */ if (_rcvbuf_get_buffer(tcb) == -ENOMEM) { + TCP_DEBUG_ERROR("-ENOMEM: Can't allocate receive buffer."); + TCP_DEBUG_LEAVE; return -ENOMEM; } @@ -239,6 +250,7 @@ static int _fsm_call_open(gnrc_tcp_tcb_t *tcb) ret = _transition_to(tcb, FSM_STATE_SYN_SENT); if (ret < 0) { _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return ret; } @@ -249,6 +261,7 @@ static int _fsm_call_open(gnrc_tcp_tcb_t *tcb) _pkt_setup_retransmit(tcb, out_pkt, false); _pkt_send(tcb, out_pkt, seq_con, false); } + TCP_DEBUG_LEAVE; return ret; } @@ -263,8 +276,7 @@ static int _fsm_call_open(gnrc_tcp_tcb_t *tcb) */ static int _fsm_call_send(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) { - DEBUG("gnrc_tcp_fsm.c : _fsm_call_send()\n"); - + TCP_DEBUG_ENTER; size_t payload = (tcb->snd_una + tcb->snd_wnd) - tcb->snd_nxt; /* Check if window is open and all packets were transmitted */ @@ -280,8 +292,10 @@ static int _fsm_call_send(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) _pkt_build(tcb, &out_pkt, &seq_con, MSK_ACK | MSK_PSH, tcb->snd_nxt, tcb->rcv_nxt, buf, payload); _pkt_setup_retransmit(tcb, out_pkt, false); _pkt_send(tcb, out_pkt, seq_con, false); + TCP_DEBUG_LEAVE; return payload; } + TCP_DEBUG_LEAVE; return 0; } @@ -296,9 +310,10 @@ static int _fsm_call_send(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) */ static int _fsm_call_recv(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) { - DEBUG("gnrc_tcp_fsm.c : _fsm_call_recv()\n"); + TCP_DEBUG_ENTER; if (ringbuffer_empty(&tcb->rcv_buf)) { + TCP_DEBUG_LEAVE; return 0; } @@ -315,6 +330,7 @@ static int _fsm_call_recv(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) _pkt_build(tcb, &out_pkt, &seq_con, MSK_ACK, tcb->snd_nxt, tcb->rcv_nxt, NULL, 0); _pkt_send(tcb, out_pkt, seq_con, false); } + TCP_DEBUG_LEAVE; return rcvd; } @@ -327,7 +343,7 @@ static int _fsm_call_recv(gnrc_tcp_tcb_t *tcb, void *buf, size_t len) */ static int _fsm_call_close(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_call_close()\n"); + TCP_DEBUG_ENTER; if (tcb->state == FSM_STATE_SYN_RCVD || tcb->state == FSM_STATE_ESTABLISHED || tcb->state == FSM_STATE_CLOSE_WAIT) { @@ -349,6 +365,7 @@ static int _fsm_call_close(gnrc_tcp_tcb_t *tcb) else if (tcb->state == FSM_STATE_CLOSE_WAIT) { _transition_to(tcb, FSM_STATE_LAST_ACK); } + TCP_DEBUG_LEAVE; return 0; } @@ -361,7 +378,7 @@ static int _fsm_call_close(gnrc_tcp_tcb_t *tcb) */ static int _fsm_call_abort(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_call_abort()\n"); + TCP_DEBUG_ENTER; /* A reset must be sent in case the TCB state is in one of those cases */ if (tcb->state == FSM_STATE_SYN_RCVD || tcb->state == FSM_STATE_ESTABLISHED || @@ -378,6 +395,7 @@ static int _fsm_call_abort(gnrc_tcp_tcb_t *tcb) /* From here on any state must transition into CLOSED state */ _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return 0; } @@ -392,6 +410,7 @@ static int _fsm_call_abort(gnrc_tcp_tcb_t *tcb) */ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) { + TCP_DEBUG_ENTER; gnrc_pktsnip_t *out_pkt = NULL; /* Outgoing packet */ uint16_t seq_con = 0; /* Sequence number consumption of outgoing packet */ gnrc_pktsnip_t *snp; /* Temporary packet snip */ @@ -401,13 +420,14 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) uint32_t seg_ack = 0; /* Acknowledgment number of the incoming packet */ uint32_t seg_wnd = 0; /* Receive window of the incoming packet */ - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt()\n"); /* Search for TCP header. */ snp = gnrc_pktsnip_search_type(in_pkt, GNRC_NETTYPE_TCP); tcp_hdr_t *tcp_hdr = (tcp_hdr_t *) snp->data; /* Parse packet options, return if they are malformed */ if (_option_parse(tcb, tcp_hdr) < 0) { + TCP_DEBUG_ERROR("Failed to parse TCP header options."); + TCP_DEBUG_LEAVE; return 0; } @@ -421,7 +441,8 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) #ifdef MODULE_GNRC_IPV6 snp = gnrc_pktsnip_search_type(in_pkt, GNRC_NETTYPE_IPV6); if (snp == NULL) { - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt() : incoming packet had no IPv6 header\n"); + TCP_DEBUG_ERROR("Packet contains no IPv6 header."); + TCP_DEBUG_LEAVE; return 0; } void *ip = snp->data; @@ -431,12 +452,16 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) if (tcb->state == FSM_STATE_LISTEN) { /* 1) Check RST: if RST is set: return */ if (ctl & MSK_RST) { + TCP_DEBUG_INFO("RST flag set in packet."); + TCP_DEBUG_LEAVE; return 0; } /* 2) Check ACK: if ACK is set: send RST with seq_no = ack_no and return */ if (ctl & MSK_ACK) { _pkt_build_reset_from_pkt(&out_pkt, in_pkt); _pkt_send(tcb, out_pkt, 0, false); + TCP_DEBUG_INFO("ACK flag set in packet. Send reset."); + TCP_DEBUG_LEAVE; return 0; } /* 3) Check SYN: if SYN is set prepare for incoming connection */ @@ -468,7 +493,8 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) * (reason: tmp *lst* can be true at runtime */ if (lst) { - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt() : Connection already handled\n"); + TCP_DEBUG_INFO("Connection is handled by another TCB."); + TCP_DEBUG_LEAVE; return 0; } @@ -478,19 +504,20 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) memcpy(tcb->local_addr, &((ipv6_hdr_t *)ip)->dst, sizeof(ipv6_addr_t)); memcpy(tcb->peer_addr, &((ipv6_hdr_t *)ip)->src, sizeof(ipv6_addr_t)); - /* In case peer_addr is link local: Store interface Id in tcb */ + /* In case peer_addr is link local: Store interface Id in TCB */ if (ipv6_addr_is_link_local((ipv6_addr_t *) tcb->peer_addr)) { gnrc_pktsnip_t *tmp = gnrc_pktsnip_search_type(in_pkt, GNRC_NETTYPE_NETIF); if (tmp == NULL) { - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt() :\ - incoming packet had no netif header\n"); + TCP_DEBUG_ERROR("Packet contains no netif header."); + TCP_DEBUG_LEAVE; return 0; } tcb->ll_iface = ((gnrc_netif_hdr_t *)tmp->data)->if_pid; } } #else - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt() : Received address was not stored\n"); + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); + TCP_DEBUG_LEAVE; return 0; #endif @@ -509,6 +536,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) _pkt_send(tcb, out_pkt, seq_con, false); _transition_to(tcb, FSM_STATE_SYN_RCVD); } + TCP_DEBUG_LEAVE; return 0; } /* Handle state SYN_SENT */ @@ -522,6 +550,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) _pkt_build(tcb, &out_pkt, &seq_con, MSK_RST, seg_ack, 0, NULL, 0); _pkt_send(tcb, out_pkt, seq_con, false); } + TCP_DEBUG_LEAVE; return 0; } } @@ -531,6 +560,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) if (ctl & MSK_ACK) { _transition_to(tcb, FSM_STATE_CLOSED); } + TCP_DEBUG_LEAVE; return 0; } /* 3) Check SYN: Set TCB values accordingly */ @@ -547,7 +577,8 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) memcpy(tcb->local_addr, &((ipv6_hdr_t *)ip)->dst, sizeof(ipv6_addr_t)); } #else - DEBUG("gnrc_tcp_fsm.c : _fsm_rcvd_pkt() : Received address was not stored\n"); + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); + TCP_DEBUG_LEAVE; return 0; #endif @@ -568,6 +599,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) tcb->snd_wl1 = seg_seq; tcb->snd_wl2 = seg_ack; } + TCP_DEBUG_LEAVE; return 0; } /* Handle other states */ @@ -581,6 +613,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) _pkt_build(tcb, &out_pkt, &seq_con, MSK_ACK, tcb->snd_nxt, tcb->rcv_nxt, NULL, 0); _pkt_send(tcb, out_pkt, seq_con, false); } + TCP_DEBUG_LEAVE; return 0; } /* 2) Check RST: If RST is set ... */ @@ -592,6 +625,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) else { _transition_to(tcb, FSM_STATE_CLOSED); } + TCP_DEBUG_LEAVE; return 0; } /* 3) Check SYN: If SYN is set ... */ @@ -600,10 +634,12 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) _pkt_build(tcb, &out_pkt, &seq_con, MSK_RST, tcb->snd_nxt, tcb->rcv_nxt, NULL, 0); _pkt_send(tcb, out_pkt, seq_con, false); _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return 0; } /* 4) Check ACK */ if (!(ctl & MSK_ACK)) { + TCP_DEBUG_LEAVE; return 0; } else { @@ -633,6 +669,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) _pkt_build(tcb, &out_pkt, &seq_con, MSK_ACK, tcb->snd_nxt, tcb->rcv_nxt, NULL, 0); _pkt_send(tcb, out_pkt, seq_con, false); + TCP_DEBUG_LEAVE; return 0; } /* Update receive window */ @@ -670,6 +707,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) if (tcb->state == FSM_STATE_LAST_ACK) { if (tcb->pkt_retransmit == NULL) { _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return 0; } } @@ -711,6 +749,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) if (ctl & MSK_FIN) { if (tcb->state == FSM_STATE_CLOSED || tcb->state == FSM_STATE_LISTEN || tcb->state == FSM_STATE_SYN_SENT) { + TCP_DEBUG_LEAVE; return 0; } /* Advance rcv_nxt over FIN bit */ @@ -737,6 +776,7 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) } } } + TCP_DEBUG_LEAVE; return 0; } @@ -749,8 +789,9 @@ static int _fsm_rcvd_pkt(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *in_pkt) */ static int _fsm_timeout_timewait(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_timeout_timewait()\n"); + TCP_DEBUG_ENTER; _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return 0; } @@ -763,14 +804,15 @@ static int _fsm_timeout_timewait(gnrc_tcp_tcb_t *tcb) */ static int _fsm_timeout_retransmit(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_timeout_retransmit()\n"); + TCP_DEBUG_ENTER; if (tcb->pkt_retransmit != NULL) { _pkt_setup_retransmit(tcb, tcb->pkt_retransmit, true); _pkt_send(tcb, tcb->pkt_retransmit, 0, true); } else { - DEBUG("gnrc_tcp_fsm.c : _fsm_timeout_retransmit() : Retransmit queue is empty\n"); + TCP_DEBUG_INFO("Retransmission queue is empty."); } + TCP_DEBUG_LEAVE; return 0; } @@ -783,8 +825,9 @@ static int _fsm_timeout_retransmit(gnrc_tcp_tcb_t *tcb) */ static int _fsm_timeout_connection(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_timeout_connection()\n"); + TCP_DEBUG_ENTER; _transition_to(tcb, FSM_STATE_CLOSED); + TCP_DEBUG_LEAVE; return 0; } @@ -797,14 +840,15 @@ static int _fsm_timeout_connection(gnrc_tcp_tcb_t *tcb) */ static int _fsm_send_probe(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; gnrc_pktsnip_t *out_pkt = NULL; /* Outgoing packet */ uint8_t probe_pay[] = {1}; /* Probe payload */ - DEBUG("gnrc_tcp_fsm.c : _fsm_send_probe()\n"); /* The probe sends a already acknowledged sequence no. with a garbage byte. */ _pkt_build(tcb, &out_pkt, NULL, MSK_ACK, tcb->snd_una - 1, tcb->rcv_nxt, probe_pay, sizeof(probe_pay)); _pkt_send(tcb, out_pkt, 0, false); + TCP_DEBUG_LEAVE; return 0; } @@ -817,8 +861,9 @@ static int _fsm_send_probe(gnrc_tcp_tcb_t *tcb) */ static int _fsm_clear_retransmit(gnrc_tcp_tcb_t *tcb) { - DEBUG("gnrc_tcp_fsm.c : _fsm_clear_retransmit()\n"); + TCP_DEBUG_ENTER; _clear_retransmit(tcb); + TCP_DEBUG_LEAVE; return 0; } @@ -839,9 +884,9 @@ static int _fsm_clear_retransmit(gnrc_tcp_tcb_t *tcb) static int _fsm_unprotected(gnrc_tcp_tcb_t *tcb, fsm_event_t event, gnrc_pktsnip_t *in_pkt, void *buf, size_t len) { + TCP_DEBUG_ENTER; int ret = 0; - DEBUG("gnrc_tcp_fsm.c : _fsm_unprotected()\n"); switch (event) { case FSM_EVENT_CALL_OPEN : ret = _fsm_call_open(tcb); @@ -877,11 +922,13 @@ static int _fsm_unprotected(gnrc_tcp_tcb_t *tcb, fsm_event_t event, gnrc_pktsnip ret = _fsm_clear_retransmit(tcb); break; } + TCP_DEBUG_LEAVE; return ret; } int _fsm(gnrc_tcp_tcb_t *tcb, fsm_event_t event, gnrc_pktsnip_t *in_pkt, void *buf, size_t len) { + TCP_DEBUG_ENTER; /* Lock FSM */ mutex_lock(&(tcb->fsm_lock)); @@ -898,12 +945,15 @@ int _fsm(gnrc_tcp_tcb_t *tcb, fsm_event_t event, gnrc_pktsnip_t *in_pkt, void *b } /* Unlock FSM */ mutex_unlock(&(tcb->fsm_lock)); + TCP_DEBUG_LEAVE; return result; } void _fsm_set_mbox(gnrc_tcp_tcb_t *tcb, mbox_t *mbox) { + TCP_DEBUG_ENTER; mutex_lock(&(tcb->fsm_lock)); tcb->mbox = mbox; mutex_unlock(&(tcb->fsm_lock)); + TCP_DEBUG_LEAVE; } diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_option.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_option.c index ff4cda44f669..15bb35ec9b01 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_option.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_option.c @@ -24,9 +24,11 @@ int _option_parse(gnrc_tcp_tcb_t *tcb, tcp_hdr_t *hdr) { + TCP_DEBUG_ENTER; /* Extract offset value. Return if no options are set */ uint8_t offset = GET_OFFSET(byteorder_ntohs(hdr->off_ctl)); if (offset <= TCP_HDR_OFFSET_MIN) { + TCP_DEBUG_LEAVE; return 0; } @@ -41,11 +43,12 @@ int _option_parse(gnrc_tcp_tcb_t *tcb, tcp_hdr_t *hdr) /* Examine current option */ switch (option->kind) { case TCP_OPTION_KIND_EOL: - DEBUG("gnrc_tcp_option.c : _option_parse() : EOL option found\n"); + TCP_DEBUG_INFO("EOL option found."); + TCP_DEBUG_LEAVE; return 0; case TCP_OPTION_KIND_NOP: - DEBUG("gnrc_tcp_option.c : _option_parse() : NOP option found\n"); + TCP_DEBUG_INFO("NOP option found."); opt_ptr += 1; opt_left -= 1; continue; @@ -53,30 +56,30 @@ int _option_parse(gnrc_tcp_tcb_t *tcb, tcp_hdr_t *hdr) case TCP_OPTION_KIND_MSS: if (opt_left < TCP_OPTION_LENGTH_MIN || option->length > opt_left || option->length != TCP_OPTION_LENGTH_MSS) { - - DEBUG("gnrc_tcp_option.c : _option_parse() : invalid MSS Option length.\n"); + TCP_DEBUG_ERROR("Invalid MSS option length."); + TCP_DEBUG_LEAVE; return -1; } + TCP_DEBUG_INFO("MSS option found."); tcb->mss = (option->value[0] << 8) | option->value[1]; - DEBUG("gnrc_tcp_option.c : _option_parse() : MSS option found. MSS=%"PRIu16"\n", - tcb->mss); break; default: if (opt_left >= TCP_OPTION_LENGTH_MIN) { - DEBUG("gnrc_tcp_option.c : _option_parse() : Unsupported option found.\ - KIND=%"PRIu8", LENGTH=%"PRIu8"\n", option->kind, option->length); + TCP_DEBUG_INFO("Valid, unsupported option found."); } } if ((opt_left < TCP_OPTION_LENGTH_MIN) || (option->length > opt_left) || (option->length < TCP_OPTION_LENGTH_MIN)) { - DEBUG("gnrc_tcp_option.c : _option_parse() : Invalid option. Drop Packet.\n"); + TCP_DEBUG_ERROR("Invalid option found."); + TCP_DEBUG_LEAVE; return -1; } opt_ptr += option->length; opt_left -= option->length; } + TCP_DEBUG_LEAVE; return 0; } diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_pkt.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_pkt.c index 4d3c682dfec6..5e096aea9168 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_pkt.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_pkt.c @@ -51,6 +51,7 @@ static inline uint32_t _max(const uint32_t x, const uint32_t y) int _pkt_build_reset_from_pkt(gnrc_pktsnip_t **out_pkt, gnrc_pktsnip_t *in_pkt) { + TCP_DEBUG_ENTER; tcp_hdr_t tcp_hdr_out; /* Extract headers */ @@ -94,9 +95,9 @@ int _pkt_build_reset_from_pkt(gnrc_pktsnip_t **out_pkt, gnrc_pktsnip_t *in_pkt) /* Allocate new TCB header */ tcp_snp = gnrc_pktbuf_add(NULL, &tcp_hdr_out, TCP_HDR_OFFSET_MIN * 4, GNRC_NETTYPE_TCP); if (tcp_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build_reset_from_pkt() :\ - Can't alloc buffer for TCP Header\n."); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't alloc buffer for TCP header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } *out_pkt = tcp_snp; @@ -105,10 +106,10 @@ int _pkt_build_reset_from_pkt(gnrc_pktsnip_t **out_pkt, gnrc_pktsnip_t *in_pkt) #ifdef MODULE_GNRC_IPV6 ip6_snp = gnrc_ipv6_hdr_build(tcp_snp, &(ip6_hdr->dst), &(ip6_hdr->src)); if (ip6_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build_reset_from_pkt() :\ - Can't alloc buffer for IPv6 Header.\n"); gnrc_pktbuf_release(tcp_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't alloc buffer for IPv6 header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } *out_pkt = ip6_snp; @@ -124,10 +125,10 @@ int _pkt_build_reset_from_pkt(gnrc_pktsnip_t **out_pkt, gnrc_pktsnip_t *in_pkt) /* Allocate new header and set interface id */ net_snp = gnrc_netif_hdr_build(NULL, 0, NULL, 0); if (net_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build_reset_from_pkt() :\ - Can't alloc buffer for netif Header.\n"); gnrc_pktbuf_release(ip6_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't alloc buffer for netif header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } else { @@ -137,8 +138,9 @@ int _pkt_build_reset_from_pkt(gnrc_pktsnip_t **out_pkt, gnrc_pktsnip_t *in_pkt) } } #else - DEBUG("gnrc_tcp_pkt.c : _pkt_build_reset_from_pkt() : Network Layer Module Missing\n"); + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); #endif + TCP_DEBUG_LEAVE; return 0; } @@ -146,6 +148,7 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, const uint16_t ctl, const uint32_t seq_num, const uint32_t ack_num, void *payload, const size_t payload_len) { + TCP_DEBUG_ENTER; gnrc_pktsnip_t *pay_snp = NULL; gnrc_pktsnip_t *tcp_snp = NULL; tcp_hdr_t tcp_hdr; @@ -155,8 +158,9 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, if (payload != NULL && payload_len > 0) { pay_snp = gnrc_pktbuf_add(pay_snp, payload, payload_len, GNRC_NETTYPE_UNDEF); if (pay_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build() : Can't allocate buffer for payload\n."); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't alloc buffer for payload."); + TCP_DEBUG_LEAVE; return -ENOMEM; } } @@ -180,17 +184,19 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, tcp_snp = gnrc_pktbuf_add(pay_snp, &tcp_hdr, sizeof(tcp_hdr), GNRC_NETTYPE_TCP); if (tcp_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build() : Can't allocate buffer for TCP Header\n."); gnrc_pktbuf_release(pay_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't alloc buffer for TCP header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } else { /* Resize TCP header: size = offset * 4 bytes */ if (gnrc_pktbuf_realloc_data(tcp_snp, offset * 4)) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build() : Couldn't set size of TCP header\n"); gnrc_pktbuf_release(tcp_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't realloc buffer for TCP header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } @@ -220,9 +226,10 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, gnrc_pktsnip_t *ip6_snp = gnrc_ipv6_hdr_build(tcp_snp, src_addr, dst_addr); if (ip6_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build() : Can't allocate buffer for IPv6 Header.\n"); gnrc_pktbuf_release(tcp_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't allocate buffer for IPv6 header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } else { @@ -233,9 +240,10 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, if (tcb->ll_iface > 0) { gnrc_pktsnip_t *net_snp = gnrc_netif_hdr_build(NULL, 0, NULL, 0); if (net_snp == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_build() : Can't allocate buffer for netif header.\n"); gnrc_pktbuf_release(ip6_snp); *(out_pkt) = NULL; + TCP_DEBUG_ERROR("-ENOMEM: Can't allocate buffer for netif header."); + TCP_DEBUG_LEAVE; return -ENOMEM; } else { @@ -245,7 +253,7 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, } } #else - DEBUG("gnrc_tcp_pkt.c : _pkt_build_reset_from_pkt() : Network Layer Module Missing\n"); + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); #endif /* Calculate sequence space number consumption for this packet */ @@ -259,14 +267,17 @@ int _pkt_build(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t **out_pkt, uint16_t *seq_con, } *seq_con += payload_len; } + TCP_DEBUG_LEAVE; return 0; } int _pkt_send(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *out_pkt, const uint16_t seq_con, const bool retransmit) { + TCP_DEBUG_ENTER; if (out_pkt == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_send() : Packet to send is null\n"); + TCP_DEBUG_ERROR("-EINVAL: out_pkt is null."); + TCP_DEBUG_LEAVE; return -EINVAL; } @@ -283,14 +294,16 @@ int _pkt_send(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *out_pkt, const uint16_t seq_c /* Pass packet down the network stack */ if (!gnrc_netapi_dispatch_send(GNRC_NETTYPE_TCP, GNRC_NETREG_DEMUX_CTX_ALL, out_pkt)) { - DEBUG("gnrc_tcp_pkt.c : _pkt_send() : unable to send packet\n"); gnrc_pktbuf_release(out_pkt); + TCP_DEBUG_ERROR("Can't dispatch to network layer."); } + TCP_DEBUG_LEAVE; return 0; } int _pkt_chk_seq_num(const gnrc_tcp_tcb_t *tcb, const uint32_t seq_num, const uint32_t seg_len) { + TCP_DEBUG_ENTER; uint32_t l_edge = tcb->rcv_nxt; uint32_t r_edge = tcb->rcv_nxt + tcb->rcv_wnd; uint32_t last_seq = seq_num + seg_len - 1; @@ -299,6 +312,7 @@ int _pkt_chk_seq_num(const gnrc_tcp_tcb_t *tcb, const uint32_t seq_num, const ui /* Segment contains no payload and receive window is closed and */ /* sequence number is next expected number */ if (seg_len == 0 && tcb->rcv_wnd == 0 && l_edge == seq_num) { + TCP_DEBUG_LEAVE; return 0; } @@ -306,6 +320,7 @@ int _pkt_chk_seq_num(const gnrc_tcp_tcb_t *tcb, const uint32_t seq_num, const ui /* Segment contains no payload and receive window is open and */ /* sequence number falls inside the receive window */ if (seg_len == 0 && tcb->rcv_wnd > 0 && INSIDE_WND(l_edge, seq_num, r_edge)) { + TCP_DEBUG_LEAVE; return 0; } @@ -314,15 +329,18 @@ int _pkt_chk_seq_num(const gnrc_tcp_tcb_t *tcb, const uint32_t seq_num, const ui /* sequence number overlaps with receive window */ if (seg_len > 0 && tcb->rcv_wnd > 0 && (INSIDE_WND(l_edge, seq_num, r_edge) || INSIDE_WND(l_edge, last_seq, r_edge))) { + TCP_DEBUG_LEAVE; return 0; } /* Everything else is not acceptable */ + TCP_DEBUG_LEAVE; return -1; } uint32_t _pkt_get_seg_len(gnrc_pktsnip_t *pkt) { + TCP_DEBUG_ENTER; uint32_t seq = 0; uint16_t ctl = 0; gnrc_pktsnip_t *snp = gnrc_pktsnip_search_type(pkt, GNRC_NETTYPE_TCP); @@ -335,35 +353,41 @@ uint32_t _pkt_get_seg_len(gnrc_pktsnip_t *pkt) if (ctl & MSK_FIN) { seq += 1; } + TCP_DEBUG_LEAVE; return seq; } uint32_t _pkt_get_pay_len(gnrc_pktsnip_t *pkt) { + TCP_DEBUG_ENTER; uint32_t seg_len = 0; gnrc_pktsnip_t *snp = gnrc_pktsnip_search_type(pkt, GNRC_NETTYPE_UNDEF); while (snp && snp->type == GNRC_NETTYPE_UNDEF) { seg_len += snp->size; snp = snp->next; } + TCP_DEBUG_LEAVE; return seg_len; } int _pkt_setup_retransmit(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *pkt, const bool retransmit) { + TCP_DEBUG_ENTER; gnrc_pktsnip_t *snp = NULL; uint32_t ctl = 0; uint32_t len = 0; /* No packet received */ if (pkt == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_setup_retransmit() : pkt=NULL\n"); + TCP_DEBUG_ERROR("-EINVAL: pkt == NULL."); + TCP_DEBUG_LEAVE; return -EINVAL; } /* Check if retransmit queue is full and pkt is not already in retransmit queue */ if (tcb->pkt_retransmit != NULL && tcb->pkt_retransmit != pkt) { - DEBUG("gnrc_tcp_pkt.c : _pkt_setup_retransmit() : Nothing to do\n"); + TCP_DEBUG_ERROR("-ENOMEM: Retransmit queue is full."); + TCP_DEBUG_LEAVE; return -ENOMEM; } @@ -374,6 +398,7 @@ int _pkt_setup_retransmit(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *pkt, const bool r /* Check if pkt contains reset or is a pure ACK, return */ if ((ctl & MSK_RST) || (((ctl & MSK_SYN_FIN_ACK) == MSK_ACK) && len == 0)) { + TCP_DEBUG_LEAVE; return 0; } @@ -415,18 +440,21 @@ int _pkt_setup_retransmit(gnrc_tcp_tcb_t *tcb, gnrc_pktsnip_t *pkt, const bool r /* Setup retransmission timer, msg to TCP thread with ptr to TCB */ _gnrc_tcp_event_loop_sched(&tcb->event_retransmit, tcb->rto, MSG_TYPE_RETRANSMISSION, tcb); + TCP_DEBUG_LEAVE; return 0; } int _pkt_acknowledge(gnrc_tcp_tcb_t *tcb, const uint32_t ack) { + TCP_DEBUG_ENTER; uint32_t seg = 0; gnrc_pktsnip_t *snp = NULL; tcp_hdr_t *hdr; /* Retransmission queue is empty. Nothing to ACK there */ if (tcb->pkt_retransmit == NULL) { - DEBUG("gnrc_tcp_pkt.c : _pkt_acknowledge() : There is no packet to ack\n"); + TCP_DEBUG_ERROR("-ENODATA: No packet to acknowledge."); + TCP_DEBUG_LEAVE; return -ENODATA; } @@ -461,16 +489,19 @@ int _pkt_acknowledge(gnrc_tcp_tcb_t *tcb, const uint32_t ack) } } } + TCP_DEBUG_LEAVE; return 0; } uint16_t _pkt_calc_csum(const gnrc_pktsnip_t *hdr, const gnrc_pktsnip_t *pseudo_hdr, const gnrc_pktsnip_t *payload) { + TCP_DEBUG_ENTER; uint16_t csum = 0; uint16_t len = (uint16_t) hdr->size; if (pseudo_hdr == NULL) { + TCP_DEBUG_LEAVE; return 0; } @@ -496,7 +527,10 @@ uint16_t _pkt_calc_csum(const gnrc_pktsnip_t *hdr, const gnrc_pktsnip_t *pseudo_ default: /* Suppress compiler warnings */ (void) len; + TCP_DEBUG_ERROR("Missing network layer. Add module to makefile."); + TCP_DEBUG_LEAVE; return 0; } + TCP_DEBUG_LEAVE; return ~csum; } diff --git a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_rcvbuf.c b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_rcvbuf.c index 4663eb6d906f..c8e51591cf71 100644 --- a/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_rcvbuf.c +++ b/sys/net/gnrc/transport_layer/tcp/gnrc_tcp_rcvbuf.c @@ -16,6 +16,7 @@ * @author Simon Brummer */ #include +#include "internal/common.h" #include "internal/rcvbuf.h" #define ENABLE_DEBUG (0) @@ -31,11 +32,12 @@ static rcvbuf_t _static_buf; */ void _rcvbuf_init(void) { - DEBUG("gnrc_tcp_rcvbuf.c : _rcvbuf_init() : entry\n"); + TCP_DEBUG_ENTER; mutex_init(&(_static_buf.lock)); for (size_t i = 0; i < CONFIG_GNRC_TCP_RCV_BUFFERS; ++i) { _static_buf.entries[i].used = 0; } + TCP_DEBUG_LEAVE; } /** @@ -46,8 +48,8 @@ void _rcvbuf_init(void) */ static void* _rcvbuf_alloc(void) { + TCP_DEBUG_ENTER; void *result = NULL; - DEBUG("gnrc_tcp_rcvbuf.c : _rcvbuf_alloc() : Entry\n"); mutex_lock(&(_static_buf.lock)); for (size_t i = 0; i < CONFIG_GNRC_TCP_RCV_BUFFERS; ++i) { if (_static_buf.entries[i].used == 0) { @@ -57,6 +59,7 @@ static void* _rcvbuf_alloc(void) } } mutex_unlock(&(_static_buf.lock)); + TCP_DEBUG_LEAVE; return result; } @@ -67,7 +70,7 @@ static void* _rcvbuf_alloc(void) */ static void _rcvbuf_free(void * const buf) { - DEBUG("gnrc_tcp_rcvbuf.c : _rcvbuf_free() : Entry\n"); + TCP_DEBUG_ENTER; mutex_lock(&(_static_buf.lock)); for (size_t i = 0; i < CONFIG_GNRC_TCP_RCV_BUFFERS; ++i) { if ((_static_buf.entries[i].used == 1) && (buf == _static_buf.entries[i].buffer)) { @@ -75,27 +78,33 @@ static void _rcvbuf_free(void * const buf) } } mutex_unlock(&(_static_buf.lock)); + TCP_DEBUG_LEAVE; } int _rcvbuf_get_buffer(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; if (tcb->rcv_buf_raw == NULL) { tcb->rcv_buf_raw = _rcvbuf_alloc(); if (tcb->rcv_buf_raw == NULL) { - DEBUG("gnrc_tcp_rcvbuf.c : _rcvbuf_get_buffer() : Can't allocate rcv_buf_raw\n"); + TCP_DEBUG_ERROR("-ENOMEM: Failed to allocate receive buffer."); + TCP_DEBUG_LEAVE; return -ENOMEM; } else { ringbuffer_init(&tcb->rcv_buf, (char *) tcb->rcv_buf_raw, GNRC_TCP_RCV_BUF_SIZE); } } + TCP_DEBUG_LEAVE; return 0; } void _rcvbuf_release_buffer(gnrc_tcp_tcb_t *tcb) { + TCP_DEBUG_ENTER; if (tcb->rcv_buf_raw != NULL) { _rcvbuf_free(tcb->rcv_buf_raw); tcb->rcv_buf_raw = NULL; } + TCP_DEBUG_LEAVE; } diff --git a/sys/net/gnrc/transport_layer/tcp/internal/common.h b/sys/net/gnrc/transport_layer/tcp/internal/common.h index c564e37b57c4..b8de7227a6b1 100644 --- a/sys/net/gnrc/transport_layer/tcp/internal/common.h +++ b/sys/net/gnrc/transport_layer/tcp/internal/common.h @@ -114,6 +114,38 @@ extern "C" { */ #define GET_OFFSET( x ) (((x) & MSK_OFFSET) >> 12) +/** + * @brief Helper macro used to create debug message on function entry. + * + * @note Compilation units using TCP_DEBUG_ENTER must set ENABLE_DEBUG and include debug.h. + */ +#define TCP_DEBUG_ENTER DEBUG("GNRC_TCP: Enter \"%s\", File: %s(%d)\n", \ + DEBUG_FUNC, RIOT_FILE_RELATIVE, __LINE__) + +/** + * @brief Helper macro used to create debug message on function exit. + * + * @note Compilation units using TCP_DEBUG_LEAVE must set ENABLE_DEBUG and include debug.h. + */ +#define TCP_DEBUG_LEAVE DEBUG("GNRC_TCP: Leave \"%s\", File: %s(%d)\n", \ + DEBUG_FUNC, RIOT_FILE_RELATIVE, __LINE__) + +/** + * @brief Helper macro used to create debug message on error. + * + * @note Compilation units using TCP_DEBUG_ERROR must set ENABLE_DEBUG and include debug.h. + */ +#define TCP_DEBUG_ERROR(msg) DEBUG("GNRC_TCP: Error: \"%s\", Func: %s, File: %s(%d)\n", \ + msg, DEBUG_FUNC, RIOT_FILE_RELATIVE, __LINE__) + +/** + * @brief Helper macro used to create informational debug message. + * + * @note Compilation units using TCP_DEBUG_INFO must set ENABLE_DEBUG and include debug.h. + */ +#define TCP_DEBUG_INFO(msg) DEBUG("GNRC_TCP: Info: \"%s\", Func: %s, File: %s(%d)\n", \ + msg, DEBUG_FUNC, RIOT_FILE_RELATIVE, __LINE__) + /** * @brief TCB list type. */ diff --git a/tests/gnrc_tcp/tests/05-garbage-pkts.py b/tests/gnrc_tcp/tests/05-garbage-pkts.py index ce92a22c637b..1cababd0b12b 100755 --- a/tests/gnrc_tcp/tests/05-garbage-pkts.py +++ b/tests/gnrc_tcp/tests/05-garbage-pkts.py @@ -7,6 +7,7 @@ # directory for more details. import base64 +import pexpect import os import socket import sys @@ -96,6 +97,16 @@ def test_short_header(child, src_if, src_ll, dst_if, dst_l2, dst_ll, dst_port): @testfunc def test_send_ack_instead_of_syn(child, src_if, src_ll, dst_if, dst_l2, dst_ll, dst_port): + # check if any debug output is generated during `@testfunc` decorator + # execution. If so, send fewer packets to prevent the target node + # from being overwhelmed by packets and output. + debug = child.expect([pexpect.TIMEOUT, + r'GNRC_TCP: Enter "\S+", File: .+\(\d+\)\s'], timeout=1) + if debug: + count = 10 + else: + count = 1000 + # see https://github.com/RIOT-OS/RIOT/pull/12001 provided_data = base64.b64decode("rwsQf2pekYLaU+exUBBwgPDKAAA=") tcp_hdr = TCP(provided_data) @@ -103,7 +114,7 @@ def test_send_ack_instead_of_syn(child, src_if, src_ll, # set destination port to application specific port tcp_hdr.dport = dst_port sendp(Ether(dst=dst_l2) / IPv6(src=src_ll, dst=dst_ll) / tcp_hdr, - iface=src_if, verbose=0, count=1000) + iface=src_if, verbose=0, count=count) # check if server actually still works with socket.socket(socket.AF_INET6, socket.SOCK_STREAM) as sock: