Add comprehensive debug output to ETCP and loadbalancer modules

Added extensive debug logging using DEBUG_* macros to both ETCP and loadbalancer modules: ETCP Module Debug Output: - Connection creation/destruction with detailed state tracking - Packet transmission/reception with ID, size, and timestamp details - ACK processing with individual ACK entry tracking - Retransmission request processing with gap detection - RTT calculation and jitter analysis with history tracking - Payload processing with duplicate detection - Measurement sections (MEAS_TS, MEAS_RESP) handling - Timer operations (retransmission, ACK scheduling) - Memory management (allocation/free operations) - Gap detection and contiguous packet delivery - Bandwidth updates and link state changes Loadbalancer Module Debug Output: - Link selection algorithm with timing calculations - Bandwidth-based load balancing decisions - Connection initialization and timeout handling - Link activity tracking and scheduling - Bandwidth measurement processing Debug Levels Available: - TRACE: Function entry/exit, packet-level details - DEBUG: Operational flow, state changes - INFO: Important events, connections, errors - WARN: Warning conditions - ERROR: Error conditions Usage examples: - ./src/utun -d 'etcp:trace' # Maximum ETCP detail - ./src/utun -d 'etcp:debug,loadbalancer:debug' # Both modules - ./src/utun -d 'all:debug' # Everything debug level This comprehensive debug output will help trace all ETCP protocol operations, packet flows, timing calculations, load balancing decisions, and state changes for thorough debugging and development of the new modules.
2 months ago · 23bc4b396a
4 changed files with 615 additions and 60 deletions
--- a/src/etcp.c
+++ b/src/etcp.c
@ -9,6 +9,9 @@
 #include <sys/time.h>
 #include <math.h>  // For bandwidth calcs

+// Enable comprehensive debug output for ETCP module
+#define DEBUG_CATEGORY_ETCP_DETAILED 1
+
 // Constants from spec (adjusted for completeness)
 #define MAX_INFLIGHT_BYTES 65536  // Initial window
 #define RETRANS_K1 2.0f           // RTT multiplier for retrans timeout
@ -25,19 +28,31 @@ static void input_queue_cb(struct ll_queue* q, struct ll_entry* entry, void* arg

 // Timestamp diff (with wrap-around)
 static uint16_t timestamp_diff(uint16_t t1, uint16_t t2) {
-    if (t1 >= t2) return t1 - t2;
-    return (0xFFFF - t2) + t1 + 1;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "timestamp_diff: t1=%u, t2=%u", t1, t2);
+    if (t1 >= t2) {
+        uint16_t diff = t1 - t2;
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "timestamp_diff: normal case, diff=%u", diff);
+        return diff;
+    }
+    uint16_t diff = (0xFFFF - t2) + t1 + 1;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "timestamp_diff: wraparound case, diff=%u", diff);
+    return diff;
 }

 // Get current time in 0.1ms units
 uint64_t get_current_time_units() {
    struct timeval tv;
    gettimeofday(&tv, NULL);
-    return ((uint64_t)tv.tv_sec * 10000ULL) + (tv.tv_usec / 100);
+    uint64_t time_units = ((uint64_t)tv.tv_sec * 10000ULL) + (tv.tv_usec / 100);
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "get_current_time_units: tv_sec=%ld, tv_usec=%ld, result=%llu", 
+                tv.tv_sec, tv.tv_usec, (unsigned long long)time_units);
+    return time_units;
 }

 uint16_t get_current_timestamp() {
-    return (uint16_t)(get_current_time_units() & 0xFFFF);
+    uint16_t timestamp = (uint16_t)(get_current_time_units() & 0xFFFF);
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "get_current_timestamp: result=%u", timestamp);
+    return timestamp;
 }

 // Internal functions (expanded)
@ -69,8 +84,15 @@ static void update_link_bandwidth(struct ETCP_LINK* link, uint32_t new_bw);

 // Create ETCP connection (unchanged)
 struct ETCP_CONN* etcp_connection_create(struct UTUN_INSTANCE* instance) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_create: instance=%p", instance);
+    
    struct ETCP_CONN* etcp = calloc(1, sizeof(struct ETCP_CONN));
-    if (!etcp) return NULL;
+    if (!etcp) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_connection_create: failed to allocate ETCP_CONN");
+        return NULL;
+    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_create: allocated etcp=%p", etcp);
    
    etcp->instance = instance;
    etcp->input_queue = queue_new(instance->ua, instance->pkt_pool);
@ -79,53 +101,88 @@ struct ETCP_CONN* etcp_connection_create(struct UTUN_INSTANCE* instance) {
    etcp->window_size = MAX_INFLIGHT_BYTES;
    etcp->next_tx_id = 1;
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_create: queues created, mtu=%d, window_size=%u, next_tx_id=%u", 
+                etcp->mtu, etcp->window_size, etcp->next_tx_id);
+    
    // Init crypto (as per original)
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_create: initializing crypto context");
    if (sc_init_ctx(&etcp->crypto_ctx, &instance->my_keys) != SC_OK) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_connection_create: crypto initialization failed");
        etcp_connection_close(etcp);
        return NULL;
    }
    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_connection_create: successfully created ETCP connection %p", etcp);
    return etcp;
 }

 // Close connection (expanded free)
 void etcp_connection_close(struct ETCP_CONN* etcp) {
-    if (!etcp) return;
+    if (!etcp) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_connection_close: called with NULL etcp");
+        return;
+    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: closing connection %p", etcp);
    
    // Cancel timers
-    if (etcp->retrans_timer) uasync_cancel_timeout(etcp->instance->ua, etcp->retrans_timer);
-    if (etcp->ack_timer) uasync_cancel_timeout(etcp->instance->ua, etcp->ack_timer);
+    if (etcp->retrans_timer) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: canceling retrans_timer");
+        uasync_cancel_timeout(etcp->instance->ua, etcp->retrans_timer);
+    }
+    if (etcp->ack_timer) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: canceling ack_timer");
+        uasync_cancel_timeout(etcp->instance->ua, etcp->ack_timer);
+    }
    
    // Free inflight
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freeing wait_ack_list");
    inflight_packet_t* pkt = etcp->wait_ack_list;
+    int wait_ack_count = 0;
    while (pkt) {
        inflight_packet_t* next = pkt->next;
        free_inflight_packet(pkt);
        pkt = next;
+        wait_ack_count++;
    }
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freed %d packets from wait_ack_list", wait_ack_count);
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freeing wait_send_list");
    pkt = etcp->wait_send_list;
+    int wait_send_count = 0;
    while (pkt) {
        inflight_packet_t* next = pkt->next;
        free_inflight_packet(pkt);
        pkt = next;
+        wait_send_count++;
    }
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freed %d packets from wait_send_list", wait_send_count);
    
    // Free rx_list
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freeing rx_list");
    rx_packet_t* rx = etcp->rx_list;
+    int rx_count = 0;
    while (rx) {
        rx_packet_t* next = rx->next;
        free(rx->data);
        free(rx);
        rx = next;
+        rx_count++;
    }
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freed %d packets from rx_list", rx_count);
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_connection_close: freeing queues");
    queue_free(etcp->input_queue);
    queue_free(etcp->output_queue);
+    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_connection_close: connection %p closed successfully", etcp);
    free(etcp);
 }

 static void free_inflight_packet(inflight_packet_t* pkt) {
    if (pkt) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "free_inflight_packet: freeing packet %p (id=%u, data_len=%u)", 
+                    pkt, pkt->id, pkt->data_len);
        free(pkt->data);
        free(pkt);
    }
@ -133,7 +190,12 @@ static void free_inflight_packet(inflight_packet_t* pkt) {

 // Reset connection (unchanged)
 void etcp_conn_reset(struct ETCP_CONN* etcp) {
-    if (!etcp) return;
+    if (!etcp) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_conn_reset: called with NULL etcp");
+        return;
+    }
+    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_conn_reset: resetting connection %p", etcp);
    
    // Cancel timers
    if (etcp->retrans_timer) uasync_cancel_timeout(etcp->instance->ua, etcp->retrans_timer);
@ -165,6 +227,7 @@ void etcp_conn_reset(struct ETCP_CONN* etcp) {
    etcp->rx_list = NULL;
    
    // Reset state
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_conn_reset: clearing packet lists and resetting state");
    etcp->next_tx_id = 1;
    etcp->last_rx_id = 0;
    etcp->last_delivered_id = 0;
@ -179,22 +242,37 @@ void etcp_conn_reset(struct ETCP_CONN* etcp) {
    etcp->rtt_history_idx = 0;
    memset(etcp->rtt_history, 0, sizeof(etcp->rtt_history));
    // Queues cleared externally if needed
+    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_conn_reset: connection %p reset completed", etcp);
 }

 // Input decrypted packet (unchanged structure, but calls expanded processes)
 void etcp_conn_input(struct ETCP_DGRAM* pkt) {
-    if (!pkt || !pkt->link || !pkt->link->etcp) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_conn_input: pkt=%p, link=%p, etcp=%p", 
+                pkt, pkt ? pkt->link : NULL, pkt && pkt->link ? pkt->link->etcp : NULL);
+    
+    if (!pkt || !pkt->link || !pkt->link->etcp) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_conn_input: invalid parameters (pkt=%p, link=%p, etcp=%p)", 
+                    pkt, pkt ? pkt->link : NULL, pkt && pkt->link ? pkt->link->etcp : NULL);
+        return;
+    }
    
    struct ETCP_CONN* etcp = pkt->link->etcp;
    uint8_t* data = pkt->data;
    uint16_t len = pkt->data_len;
    uint16_t ts = pkt->timestamp;
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_conn_input: processing packet - etcp=%p, data_len=%u, timestamp=%u, link=%p", 
+                etcp, len, ts, pkt->link);
+    
    // Update link activity
    pkt->link->last_activity = get_current_time_units();
    pkt->link->last_recv_local_time = pkt->link->last_activity;
    pkt->link->last_recv_timestamp = ts;
    
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_conn_input: updated link activity - last_activity=%llu, last_recv_timestamp=%u", 
+                (unsigned long long)pkt->link->last_activity, pkt->link->last_recv_timestamp);
+    
    // Parse sections
    uint16_t pos = 0;
    while (pos < len) {
@ -246,16 +324,34 @@ void etcp_conn_input(struct ETCP_DGRAM* pkt) {

 // Request next packet (expanded)
 struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
-    if (!etcp) return NULL;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: etcp=%p", etcp);
+    
+    if (!etcp) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: called with NULL etcp");
+        return NULL;
+    }
+    
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: input_queue_count=%d, wait_send_list=%p, unacked_bytes=%u, window_size=%u",
+                queue_entry_count(etcp->input_queue), etcp->wait_send_list, 
+                etcp->unacked_bytes, etcp->window_size);
    
    // Check waiting conditions
    if (queue_entry_count(etcp->input_queue) == 0 && etcp->wait_send_list == NULL) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: no packets available, setting callback and returning NULL");
        // Wait for input or retrans
        // Set callback for resume
        queue_set_callback(etcp->input_queue, input_queue_cb, etcp);  // Define cb to resume
        return NULL;
    }
    
+    if (etcp->unacked_bytes >= etcp->window_size) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: window full (unacked_bytes=%u >= window_size=%u), waiting",
+                    etcp->unacked_bytes, etcp->window_size);
+        // Wait ACK or timeout
+        etcp->wait_timeout_active = 1;
+        return NULL;
+    }
+    
    if (etcp->unacked_bytes >= etcp->window_size) {
        // Wait ACK or timeout
        etcp->wait_timeout_active = 1;
@ -265,20 +361,32 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
    // Get packet (prefer retrans)
    inflight_packet_t* ipkt = etcp->wait_send_list;
    if (ipkt) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: using retransmission packet id=%u", ipkt->id);
        remove_inflight(etcp, ipkt);
    } else {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: getting new packet from input queue");
        struct ll_entry* entry = queue_entry_get(etcp->input_queue);
-        if (!entry) return NULL;
+        if (!entry) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: no entry available from input queue");
+            return NULL;
+        }
        
        ipkt = calloc(1, sizeof(inflight_packet_t));
        if (!ipkt) {
+            DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: failed to allocate inflight_packet_t");
            queue_entry_put_first(etcp->input_queue, entry);
            return NULL;
        }
+        
        ipkt->id = etcp->next_tx_id++;
        ipkt->data_len = ll_entry_size(entry);
        ipkt->data = malloc(ipkt->data_len);
+        
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: created new packet id=%u, data_len=%u", 
+                    ipkt->id, ipkt->data_len);
+        
        if (!ipkt->data) {
+            DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: failed to allocate packet data buffer");
            free(ipkt);
            queue_entry_put_first(etcp->input_queue, entry);
            return NULL;
@ -289,10 +397,13 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
    }
    
    // Select link
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: selecting link via loadbalancer");
    struct ETCP_LINK* link = etcp_loadbalancer_select_link(etcp);
    if (!link) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: no suitable link available");
        // Put back if new
        if (ipkt->send_count == 0) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: putting new packet back to input queue");
            struct ll_entry* entry = queue_entry_new(ipkt->data_len);
            memcpy(ll_entry_data(entry), ipkt->data, ipkt->data_len);
            queue_entry_put_first(etcp->input_queue, entry);
@ -301,14 +412,22 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
        return NULL;
    }
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: selected link %p", link);
+    
    // Build packet buf
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: building packet with optional sections");
    uint8_t buf[1600];
    uint16_t len = append_optional_sections(etcp, buf, link);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: optional sections added, len=%u", len);
    
    // Add payload (assume payload includes ID as first 2 bytes)
    uint16_t pay_len = ipkt->payload_len + 2;  // ID
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: payload section - pay_len=%u (payload_len=%u + 2 for ID)", 
+                pay_len, ipkt->payload_len);
+    
    if (len + SECTION_HEADER_SIZE + pay_len > sizeof(buf)) {
-        // Too large
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: packet too large (%u + %u + %u > %u), dropping", 
+                    len, SECTION_HEADER_SIZE, pay_len, (unsigned)sizeof(buf));
        free_inflight_packet(ipkt);
        return NULL;
    }
@ -319,10 +438,12 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
    buf[len++] = ipkt->id & 0xFF;
    memcpy(buf + len, ipkt->data, ipkt->payload_len);
    len += ipkt->payload_len;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: payload added, total len=%u", len);
    
    // Alloc dgram
    struct ETCP_DGRAM* dgram = memory_pool_alloc(etcp->instance->pkt_pool);
    if (!dgram) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: failed to allocate dgram from memory pool");
        free_inflight_packet(ipkt);
        return NULL;
    }
@ -332,6 +453,9 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
    dgram->timestamp = get_current_timestamp();
    memcpy(dgram->data, buf, len);
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: allocated dgram %p (link=%p, data_len=%u, timestamp=%u)", 
+                dgram, link, len, dgram->timestamp);
+    
    // Update inflight
    ipkt->last_link = link;
    ipkt->last_timestamp = dgram->timestamp;
@ -339,19 +463,30 @@ struct ETCP_DGRAM* etcp_request_pkt(struct ETCP_CONN* etcp) {
    etcp->unacked_bytes += ipkt->payload_len;
    etcp->bytes_sent_total += len;  // Approx
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: updated inflight - send_count=%u, unacked_bytes=%u, bytes_sent_total=%u", 
+                ipkt->send_count, etcp->unacked_bytes, etcp->bytes_sent_total);
+    
    // Move to wait_ack
    ipkt->state = INFLIGHT_STATE_WAIT_ACK;
    ipkt->next = etcp->wait_ack_list;
    etcp->wait_ack_list = ipkt;
    
+    // Add to wait_ack list
+    ipkt->next = etcp->wait_ack_list;
+    etcp->wait_ack_list = ipkt;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: added packet %u to wait_ack_list", ipkt->id);
+    
    // Start retrans timer if empty before
    if (etcp->wait_ack_list->next == NULL && !etcp->retrans_timer) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: starting retrans_timer (wait_ack_list was empty)");
        etcp->retrans_timer = uasync_set_timeout(etcp->instance->ua, 20, etcp, retrans_timer_cb);
    }
    
    // Update load balancer after send (call from connections after actual send)
    // etcp_loadbalancer_update_after_send(link, len + headers);  // Assume called externally
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_request_pkt: successfully created dgram %p for packet id=%u", 
+                dgram, ipkt->id);
    return dgram;
 }

@ -364,9 +499,12 @@ static void input_queue_cb(struct ll_queue* q, struct ll_entry* entry, void* arg
    queue_resume_callback(q);
 }

-// Append optional (expanded: build ACK, RETRANS, TIMESTAMP)
+// Append optional (expanded with debug)
 static uint16_t append_optional_sections(struct ETCP_CONN* etcp, uint8_t* buf, struct ETCP_LINK* link) {
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "append_optional_sections: etcp=%p, link=%p", etcp, link);
+    
    uint16_t len = 0;
+    int sections_added = 0;
    
    // Timestamp (assume 2 bytes TS)
    uint16_t ts = get_current_timestamp();
@ -375,6 +513,8 @@ static uint16_t append_optional_sections(struct ETCP_CONN* etcp, uint8_t* buf, s
    buf[len++] = 2;  // len low
    buf[len++] = (ts >> 8) & 0xFF;
    buf[len++] = ts & 0xFF;
+    sections_added++;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "append_optional_sections: added TIMESTAMP section (ts=%u, len=%u)", ts, len);
    
    // ACK (assume count(1) + [id(2)+ts(2)]*count)
    if (etcp->pending_ack_count > 0) {
@ -383,6 +523,9 @@ static uint16_t append_optional_sections(struct ETCP_CONN* etcp, uint8_t* buf, s
        buf[len++] = (ack_len >> 8) & 0xFF;
        buf[len++] = ack_len & 0xFF;
        buf[len++] = etcp->pending_ack_count;
+        
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: adding ACK section with %u ACKs", etcp->pending_ack_count);
+        
        for (uint8_t i = 0; i < etcp->pending_ack_count; i++) {
            uint16_t id = etcp->pending_ack_ids[i];
            uint16_t ats = etcp->pending_ack_ts[i];
@ -390,9 +533,13 @@ static uint16_t append_optional_sections(struct ETCP_CONN* etcp, uint8_t* buf, s
            buf[len++] = id & 0xFF;
            buf[len++] = (ats >> 8) & 0xFF;
            buf[len++] = ats & 0xFF;
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "append_optional_sections: ACK[%u] - id=%u, ts=%u", i, id, ats);
        }
+        
        etcp->pending_ack_count = 0;
        etcp->ack_packets_count++;
+        sections_added++;
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: added ACK section (total_len=%u)", len);
    }
    
    // RETRANS (similar: count(1) + id(2)*count)
@ -402,124 +549,227 @@ static uint16_t append_optional_sections(struct ETCP_CONN* etcp, uint8_t* buf, s
        buf[len++] = (ret_len >> 8) & 0xFF;
        buf[len++] = ret_len & 0xFF;
        buf[len++] = etcp->pending_retrans_count;
+        
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: adding RETRANS section with %u requests", etcp->pending_retrans_count);
+        
        for (uint8_t i = 0; i < etcp->pending_retrans_count; i++) {
            uint16_t id = etcp->pending_retrans_ids[i];
            buf[len++] = (id >> 8) & 0xFF;
            buf[len++] = id & 0xFF;
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "append_optional_sections: RETRANS[%u] - id=%u", i, id);
        }
+        
        etcp->pending_retrans_count = 0;
+        sections_added++;
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: added RETRANS section (total_len=%u)", len);
    }
    
    // MEAS_TS if burst (assume [start_id(2)][n(1)])
    if (etcp->burst_in_progress) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: burst measurement in progress, would add MEAS_TS");
        // Logic for adding to burst packets
        // Placeholder
    }
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "append_optional_sections: completed - added %u sections, total_len=%u", 
+                sections_added, len);
+    
    return len;
 }

 // Process ACK (expanded)
 static void process_section_ack(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
-    if (len < 1) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_ack: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
+    if (len < 1) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_ack: invalid length %u", len);
+        return;
+    }
    uint8_t count = data[0];
-    if (1 + count * 4 > len) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_ack: count=%u", count);
+    
+    if (1 + count * 4 > len) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "process_section_ack: invalid count %u for len %u", count, len);
+        return;
+    }
    
    uint16_t lp_ts = 0;
+    int acked_count = 0;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_ack: processing %u ACK entries", count);
+    
    for (uint8_t i = 0; i < count; i++) {
        uint16_t id = (data[1 + i*4] << 8) | data[2 + i*4];
        uint16_t ts = (data[3 + i*4] << 8) | data[4 + i*4];
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_ack: entry %u - id=%u, ts=%u", i, id, ts);
+        
        inflight_packet_t* pkt = find_inflight(etcp, id, INFLIGHT_STATE_WAIT_ACK);
        if (pkt) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_ack: found inflight packet %u, removing (payload_len=%u)", 
+                        id, pkt->payload_len);
            etcp->unacked_bytes -= pkt->payload_len;
            remove_inflight(etcp, pkt);
            free_inflight_packet(pkt);
            lp_ts = ts;  // Update last positive ts
+            acked_count++;
+        } else {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_ack: no inflight packet found for id=%u", id);
        }
    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_ack: successfully ACKed %u/%u packets", acked_count, count);
    // Use lp_ts in retrans_check if needed
    etcp->last_rx_ack_id = (data[1 + (count-1)*4] << 8) | data[2 + (count-1)*4];  // Last ACK ID
 }

 // Process RETRANS (expanded)
 static void process_section_retrans(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
-    if (len < 1) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_retrans: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
+    if (len < 1) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_retrans: invalid length %u", len);
+        return;
+    }
    uint8_t count = data[0];
-    if (1 + count * 2 > len) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_retrans: count=%u", count);
+    
+    if (1 + count * 2 > len) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "process_section_retrans: invalid count %u for len %u", count, len);
+        return;
+    }
+    
+    int retrans_count = 0;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_retrans: processing %u retrans requests", count);
    
    for (uint8_t i = 0; i < count; i++) {
        uint16_t id = (data[1 + i*2] << 8) | data[2 + i*2];
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_retrans: requesting retrans for id=%u", id);
+        
        inflight_packet_t* pkt = find_inflight(etcp, id, INFLIGHT_STATE_WAIT_ACK);
        if (pkt) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_retrans: found packet %u, marking for retransmission", id);
            pkt->retrans_req_count++;
            pkt->need_retrans = 1;
            move_to_wait_send(etcp, pkt);
+            retrans_count++;
+        } else {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_retrans: no inflight packet found for id=%u", id);
        }
    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_retrans: marked %u/%u packets for retransmission", retrans_count, count);
 }

 // Process TIMESTAMP (expanded)
 static void process_section_timestamp(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
-    if (len != 2) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_timestamp: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
+    if (len != 2) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_timestamp: invalid length %u (expected 2)", len);
+        return;
+    }
    uint16_t recv_ts = (data[0] << 8) | data[1];
-    uint16_t rtt = timestamp_diff(get_current_timestamp(), recv_ts);
+    uint16_t current_ts = get_current_timestamp();
+    uint16_t rtt = timestamp_diff(current_ts, recv_ts);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_timestamp: recv_ts=%u, current_ts=%u, calculated_rtt=%u", 
+                recv_ts, current_ts, rtt);
    update_rtt(etcp, rtt);
 }

 // Process PAYLOAD (expanded)
 static void process_section_payload(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
-    if (len < 2) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
+    if (len < 2) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_payload: invalid length %u (minimum 2)", len);
+        return;
+    }
    uint16_t id = (data[0] << 8) | data[1];
-    if (id <= etcp->last_rx_id) return;  // Dup
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: packet id=%u, last_rx_id=%u", id, etcp->last_rx_id);
+    
+    if (id <= etcp->last_rx_id) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_payload: duplicate packet id=%u (last_rx_id=%u), ignoring", 
+                    id, etcp->last_rx_id);
+        return;  // Dup
+    }
    
    rx_packet_t* new_rx = calloc(1, sizeof(rx_packet_t));
-    if (!new_rx) return;
+    if (!new_rx) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "process_section_payload: failed to allocate rx_packet_t");
+        return;
+    }
+    
    new_rx->id = id;
    new_rx->timestamp = get_current_timestamp();
    new_rx->data_len = len - 2;
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: allocated rx_packet %p (id=%u, data_len=%u, timestamp=%u)", 
+                new_rx, new_rx->id, new_rx->data_len, new_rx->timestamp);
+    
    new_rx->data = malloc(new_rx->data_len);
    if (!new_rx->data) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "process_section_payload: failed to allocate rx data buffer (size=%u)", new_rx->data_len);
        free(new_rx);
        return;
    }
    memcpy(new_rx->data, data + 2, new_rx->data_len);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: copied %u bytes of payload data", new_rx->data_len);
    
    // Insert sorted (assume IDs sequential, no wrap for simplicity)
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_payload: inserting packet into rx_list (id=%u)", id);
    rx_packet_t** ptr = &etcp->rx_list;
    while (*ptr && (*ptr)->id < id) ptr = &(*ptr)->next;
    if (*ptr && (*ptr)->id == id) {
-        // Dup
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_payload: duplicate packet id=%u found in rx_list, discarding", id);
        free(new_rx->data);
        free(new_rx);
        return;
    }
    new_rx->next = *ptr;
    *ptr = new_rx;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: successfully inserted packet id=%u into rx_list", id);
    
-    if (id > etcp->last_rx_id) etcp->last_rx_id = id;
+    if (id > etcp->last_rx_id) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_payload: updating last_rx_id from %u to %u", 
+                    etcp->last_rx_id, id);
+        etcp->last_rx_id = id;
+    }
    
    // Pending ACK
    if (etcp->pending_ack_count < MAX_PENDING) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "process_section_payload: adding packet id=%u to pending ACKs (count=%u)", 
+                    id, etcp->pending_ack_count + 1);
        etcp->pending_ack_ids[etcp->pending_ack_count] = id;
        etcp->pending_ack_ts[etcp->pending_ack_count++] = new_rx->timestamp;
+    } else {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_payload: pending ACK buffer full (%u), cannot add id=%u", 
+                  MAX_PENDING, id);
    }
    
    // Schedule ACK
    if (!etcp->ack_timer) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: scheduling ACK timer (delay=%u tb)", ACK_DELAY_TB);
        etcp->ack_timer = uasync_set_timeout(etcp->instance->ua, ACK_DELAY_TB, etcp, ack_timer_cb);
    }
    
    etcp->bytes_received_total += len;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_payload: packet id=%u processed successfully, bytes_received_total=%u", 
+                id, etcp->bytes_received_total);
 }

 // Process MEAS_TS (expanded: send resp)
 static void process_section_meas_ts(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
-    if (len < 3) return;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_meas_ts: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
+    if (len < 3) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_meas_ts: invalid length %u (minimum 3)", len);
+        return;
+    }
    uint16_t start_id = (data[0] << 8) | data[1];
    uint8_t n = data[2];
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_meas_ts: start_id=%u, n=%u", start_id, n);
+    
    // Send MEAS_RESP (add to pending or direct)
    // Placeholder: assume added to next packet
-    // For testing, log
    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "MEAS_TS: start_id=%u n=%u", start_id, n);
    // Build resp [start_id(2)][n(1)][recv_ts(2)]
    // But since appended in optional, set state
@ -527,11 +777,17 @@ static void process_section_meas_ts(struct ETCP_CONN* etcp, uint8_t* data, uint1

 // Process MEAS_RESP (expanded: calc bw)
 static void process_section_meas_resp(struct ETCP_CONN* etcp, uint8_t* data, uint16_t len) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_meas_resp: etcp=%p, data=%p, len=%u", etcp, data, len);
+    
    // Assume format [start_id(2)][n(1)][recv_ts(2)]
-    if (len < 5) return;
+    if (len < 5) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "process_section_meas_resp: invalid length %u (minimum 5)", len);
+        return;
+    }
    uint16_t start_id = (data[0] << 8) | data[1];
    uint8_t n = data[2];
    uint16_t recv_ts = (data[3] << 8) | data[4];
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "process_section_meas_resp: start_id=%u, n=%u, recv_ts=%u", start_id, n, recv_ts);
    
    if (etcp->burst_start_id != start_id || !etcp->burst_in_progress) return;
    
@ -544,51 +800,111 @@ static void process_section_meas_resp(struct ETCP_CONN* etcp, uint8_t* data, uin

 // Detect gaps (expanded)
 static void detect_gaps_and_request_retrans(struct ETCP_CONN* etcp) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: etcp=%p, last_delivered_id=%u", 
+                etcp, etcp->last_delivered_id);
+    
    rx_packet_t* rx = etcp->rx_list;
    uint16_t expected = etcp->last_delivered_id + 1;
+    int gaps_found = 0;
+    int retrans_requested = 0;
+    
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: starting gap detection from expected_id=%u", expected);
+    
    while (rx) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: checking rx packet id=%u (expected=%u)", 
+                    rx->id, expected);
+        
        if (rx->id > expected) {
            // Gap: add retrans for expected to rx->id -1
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: gap detected - expected=%u, found=%u", 
+                        expected, rx->id);
+            gaps_found++;
+            
            for (uint16_t gid = expected; gid < rx->id && etcp->pending_retrans_count < MAX_PENDING; gid++) {
                etcp->pending_retrans_ids[etcp->pending_retrans_count++] = gid;
+                retrans_requested++;
+                DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: queued retrans request for id=%u", gid);
            }
            expected = rx->id + 1;
        } else if (rx->id == expected) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: found expected packet id=%u", expected);
            expected++;
+        } else {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: packet id=%u < expected=%u, already processed", 
+                        rx->id, expected);
        }
        rx = rx->next;
    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "detect_gaps_and_request_retrans: completed - gaps_found=%d, retrans_requested=%u", 
+                gaps_found, retrans_requested);
 }

-// Deliver contiguous (unchanged)
+// Deliver contiguous (expanded)
 static void deliver_contiguous_packets(struct ETCP_CONN* etcp) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "deliver_contiguous_packets: etcp=%p, last_delivered_id=%u", 
+                etcp, etcp->last_delivered_id);
+    
    rx_packet_t** ptr = &etcp->rx_list;
+    int delivered_count = 0;
+    uint32_t delivered_bytes = 0;
+    
    while (*ptr && (*ptr)->id == etcp->last_delivered_id + 1) {
        rx_packet_t* rx = *ptr;
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "deliver_contiguous_packets: delivering packet id=%u (data_len=%u)", 
+                    rx->id, rx->data_len);
+        
        struct ll_entry* entry = queue_entry_new(rx->data_len);
        if (entry) {
            memcpy(ll_entry_data(entry), rx->data, rx->data_len);
            queue_entry_put(etcp->output_queue, entry);
+            delivered_bytes += rx->data_len;
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "deliver_contiguous_packets: queued packet id=%u to output_queue", rx->id);
+        } else {
+            DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "deliver_contiguous_packets: failed to allocate queue entry for packet id=%u", rx->id);
        }
+        
        etcp->last_delivered_id = rx->id;
        *ptr = rx->next;
        free(rx->data);
        free(rx);
+        delivered_count++;
    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "deliver_contiguous_packets: delivered %u contiguous packets (%u bytes), last_delivered_id=%u", 
+                delivered_count, delivered_bytes, etcp->last_delivered_id);
 }

 // Retrans check (expanded with lp_ts)
 static void retrans_check(struct ETCP_CONN* etcp) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: etcp=%p, wait_ack_list=%p, rtt_avg_10=%u, jitter=%u", 
+                etcp, etcp->wait_ack_list, etcp->rtt_avg_10, etcp->jitter);
+    
    uint64_t now = get_current_time_units();
    inflight_packet_t** ptr = &etcp->wait_ack_list;
    uint16_t lp_ts = 0;
+    int checked_packets = 0;
+    int retrans_packets = 0;
+    uint16_t timeout_calc = (uint16_t)(etcp->rtt_avg_10 * RETRANS_K1 + etcp->jitter * RETRANS_K2);
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: timeout calculation: rtt_avg_10=%u * %.1f + jitter=%u * %.1f = %u", 
+                etcp->rtt_avg_10, RETRANS_K1, etcp->jitter, RETRANS_K2, timeout_calc);
+    
    while (*ptr) {
        inflight_packet_t* pkt = *ptr;
+        checked_packets++;
        uint16_t timeout = (uint16_t)(etcp->rtt_avg_10 * RETRANS_K1 + etcp->jitter * RETRANS_K2);
-        if (timestamp_diff(now, pkt->last_timestamp) > timeout) {
+        uint16_t time_since_send = timestamp_diff(now, pkt->last_timestamp);
+        
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "retrans_check: checking packet id=%u (time_since_send=%u, timeout=%u, need_retrans=%u)", 
+                    pkt->id, time_since_send, timeout, pkt->need_retrans);
+        
+        if (time_since_send > timeout) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: packet id=%u timed out, marking for retransmission", pkt->id);
            pkt->need_retrans = 1;
            move_to_wait_send(etcp, pkt);
            etcp->retransmissions_count++;
+            retrans_packets++;
            ptr = &etcp->wait_ack_list;  // Restart scan after move
            continue;
        }
@ -597,97 +913,200 @@ static void retrans_check(struct ETCP_CONN* etcp) {
        ptr = &pkt->next;
    }
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: completed - checked %d packets, retransmitted %d packets, total_retransmissions=%u", 
+                checked_packets, retrans_packets, etcp->retransmissions_count);
+    
    // Reschedule if list not empty
    if (etcp->wait_ack_list) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: rescheduling retrans_timer (wait_ack_list not empty)");
        etcp->retrans_timer = uasync_set_timeout(etcp->instance->ua, 20, etcp, retrans_timer_cb);
    } else {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_check: clearing retrans_timer (wait_ack_list empty)");
        etcp->retrans_timer = NULL;
    }
 }

-// Find inflight (unchanged)
+// Find inflight (expanded)
 static inflight_packet_t* find_inflight(struct ETCP_CONN* etcp, uint16_t id, uint8_t state) {
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "find_inflight: etcp=%p, id=%u, state=%u", etcp, id, state);
+    
    inflight_packet_t* list = (state == INFLIGHT_STATE_WAIT_ACK) ? etcp->wait_ack_list : etcp->wait_send_list;
-    while (list) {
-        if (list->id == id) return list;
-        list = list->next;
+    inflight_packet_t* pkt = list;
+    int position = 0;
+    
+    while (pkt && pkt->id != id) {
+        pkt = pkt->next;
+        position++;
    }
-    return NULL;
+    
+    if (pkt) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "find_inflight: found packet %u at position %d in %s list", 
+                    id, position, (state == INFLIGHT_STATE_WAIT_ACK) ? "wait_ack" : "wait_send");
+    } else {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "find_inflight: packet %u not found in %s list", 
+                    id, (state == INFLIGHT_STATE_WAIT_ACK) ? "wait_ack" : "wait_send");
+    }
+    
+    return pkt;
+    return pkt;
 }

-// Move to wait_send (unchanged)
+// Move to wait_send (expanded)
 static void move_to_wait_send(struct ETCP_CONN* etcp, inflight_packet_t* pkt) {
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "move_to_wait_send: etcp=%p, pkt=%p (id=%u, state=%u)", 
+                etcp, pkt, pkt->id, pkt->state);
+    
    remove_inflight(etcp, pkt);
    pkt->state = INFLIGHT_STATE_WAIT_SEND;
    pkt->next = etcp->wait_send_list;
    etcp->wait_send_list = pkt;
+    
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "move_to_wait_send: moved packet %u to wait_send_list", pkt->id);
 }

-// Remove inflight (unchanged)
+// Remove inflight (expanded)
 static void remove_inflight(struct ETCP_CONN* etcp, inflight_packet_t* pkt) {
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "remove_inflight: etcp=%p, pkt=%p (id=%u, state=%u)", 
+                etcp, pkt, pkt->id, pkt->state);
+    
    inflight_packet_t** list = (pkt->state == INFLIGHT_STATE_WAIT_ACK) ? &etcp->wait_ack_list : &etcp->wait_send_list;
    inflight_packet_t** ptr = list;
-    while (*ptr && *ptr != pkt) ptr = &(*ptr)->next;
-    if (*ptr) *ptr = (*ptr)->next;
+    int position = 0;
+    
+    while (*ptr && *ptr != pkt) {
+        ptr = &(*ptr)->next;
+        position++;
+    }
+    
+    if (*ptr) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "remove_inflight: found packet %u at position %d in %s list", 
+                    pkt->id, position, (pkt->state == INFLIGHT_STATE_WAIT_ACK) ? "wait_ack" : "wait_send");
+        *ptr = (*ptr)->next;
+    } else {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "remove_inflight: packet %u not found in %s list", 
+                  pkt->id, (pkt->state == INFLIGHT_STATE_WAIT_ACK) ? "wait_ack" : "wait_send");
+    }
 }

 // Start burst (placeholder expanded)
 static void start_burst_measurement(struct ETCP_CONN* etcp, struct ETCP_LINK* link) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "start_burst_measurement: etcp=%p, link=%p", etcp, link);
+    
    // Periodically call this
    etcp->burst_in_progress = 1;
+    uint16_t old_start_id = etcp->burst_start_id;
    etcp->burst_start_id = etcp->next_tx_id;
+    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "start_burst_measurement: started burst measurement - burst_start_id=%u (was %u)", 
+                etcp->burst_start_id, old_start_id);
+    
    // Delay first, then burst 4
    // Assume handled in request_pkt by adding meas_ts to next BURST_SIZE pkts
 }

-// Update link bw (add bandwidth to ETCP_LINK in etcp_connections.h)
-/// In ETCP_LINK add: uint32_t bandwidth;  // bits/sec
+// Update link bw (expanded)
 static void update_link_bandwidth(struct ETCP_LINK* link, uint32_t new_bw) {
-    link->bandwidth = (link->bandwidth * 0.9) + (new_bw * 0.1);  // Smooth
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "update_link_bandwidth: link=%p, new_bw=%u bits/sec (current=%u)", 
+                link, new_bw, link->bandwidth);
+    
+    uint32_t old_bw = link->bandwidth;
+    link->bandwidth = (uint32_t)((link->bandwidth * 0.9) + (new_bw * 0.1));  // Smooth
+    
+    DEBUG_INFO(DEBUG_CATEGORY_ETCP, "update_link_bandwidth: updated link bandwidth from %u to %u bits/sec (new_bw=%u)", 
+                old_bw, link->bandwidth, new_bw);
 }

 // Update RTT (expanded with history)
 static void update_rtt(struct ETCP_CONN* etcp, uint16_t new_rtt) {
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "update_rtt: etcp=%p, new_rtt=%u (last_rtt=%u, avg_10=%u, avg_100=%u)", 
+                etcp, new_rtt, etcp->rtt_last, etcp->rtt_avg_10, etcp->rtt_avg_100);
+    
    etcp->rtt_last = new_rtt;
    etcp->rtt_avg_10 = (etcp->rtt_avg_10 * 9 + new_rtt) / 10;
    etcp->rtt_avg_100 = (etcp->rtt_avg_100 * 99 + new_rtt) / 100;
    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "update_rtt: updated RTT metrics - last=%u, avg_10=%u, avg_100=%u", 
+                etcp->rtt_last, etcp->rtt_avg_10, etcp->rtt_avg_100);
+    
    // History for jitter
    etcp->rtt_history[etcp->rtt_history_idx++] = new_rtt;
    if (etcp->rtt_history_idx >= RTT_HISTORY_SIZE) etcp->rtt_history_idx = 0;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "update_rtt: stored RTT in history at index %u", 
+                (etcp->rtt_history_idx + RTT_HISTORY_SIZE - 1) % RTT_HISTORY_SIZE);
+    
    calculate_jitter(etcp);
 }

 static void calculate_jitter(struct ETCP_CONN* etcp) {
    uint16_t min_rtt = UINT16_MAX;
    uint16_t max_rtt = 0;
+    int valid_samples = 0;
+    
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "calculate_jitter: analyzing RTT history (history_idx=%u)", etcp->rtt_history_idx);
+    
    for (int i = 0; i < RTT_HISTORY_SIZE; i++) {
-        if (etcp->rtt_history[i] == 0) continue;
-        if (etcp->rtt_history[i] < min_rtt) min_rtt = etcp->rtt_history[i];
-        if (etcp->rtt_history[i] > max_rtt) max_rtt = etcp->rtt_history[i];
+        if (etcp->rtt_history[i] == 0) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "calculate_jitter: history[%d] = 0 (invalid), skipping", i);
+            continue;
+        }
+        valid_samples++;
+        if (etcp->rtt_history[i] < min_rtt) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "calculate_jitter: new min_rtt=%u (was %u) at history[%d]", 
+                        etcp->rtt_history[i], min_rtt, i);
+            min_rtt = etcp->rtt_history[i];
+        }
+        if (etcp->rtt_history[i] > max_rtt) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "calculate_jitter: new max_rtt=%u (was %u) at history[%d]", 
+                        etcp->rtt_history[i], max_rtt, i);
+            max_rtt = etcp->rtt_history[i];
+        }
    }
+    
+    uint16_t old_jitter = etcp->jitter;
    etcp->jitter = max_rtt - min_rtt;
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "calculate_jitter: completed - valid_samples=%d, min_rtt=%u, max_rtt=%u, jitter=%u (was %u)", 
+                valid_samples, min_rtt, max_rtt, etcp->jitter, old_jitter);
 }

-// Timers (unchanged)
+// Timers (expanded with debug)
 static void retrans_timer_cb(void* arg) {
-    struct ETCP_CONN* etcp = arg;
+    struct ETCP_CONN* etcp = (struct ETCP_CONN*)arg;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "retrans_timer_cb: etcp=%p, triggered retransmission check", etcp);
    retrans_check(etcp);
 }

 static void ack_timer_cb(void* arg) {
-    struct ETCP_CONN* etcp = arg;
+    struct ETCP_CONN* etcp = (struct ETCP_CONN*)arg;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "ack_timer_cb: etcp=%p, processing pending ACKs", etcp);
    etcp->ack_timer = NULL;
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "ack_timer_cb: processing %u pending ACKs", etcp->pending_ack_count);
+    
    // Force send ACK if pending (e.g., empty payload pkt)
    // For now, assume appended next
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "ack_timer_cb: ACK processing completed");
 }

 // Get stats (expanded)
 void etcp_get_stats(struct ETCP_CONN* etcp, size_t* packets_sent, size_t* packets_recv,
                    size_t* pool_allocs, size_t* pool_reuse) {
-    if (packets_sent) *packets_sent = etcp->total_packets_sent;
-    if (packets_recv) *packets_recv = etcp->bytes_received_total / 1400;  // Approx MTU
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: etcp=%p", etcp);
+    
+    if (packets_sent) {
+        *packets_sent = etcp->total_packets_sent;
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: total_packets_sent=%zu", *packets_sent);
+    }
+    if (packets_recv) {
+        *packets_recv = etcp->bytes_received_total / 1400;  // Approx MTU
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: bytes_received_total=%u, estimated_packets=%zu", 
+                    etcp->bytes_received_total, *packets_recv);
+    }
    if (pool_allocs || pool_reuse) {
+        DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: getting memory pool stats");
        memory_pool_get_stats(etcp->instance->pkt_pool, pool_allocs, pool_reuse);
+        if (pool_allocs) DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: pool_allocs=%zu", *pool_allocs);
+        if (pool_reuse) DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_get_stats: pool_reuse=%zu", *pool_reuse);
    }
 }
--- a/src/etcp_loadbalancer.c
+++ b/src/etcp_loadbalancer.c
@ -4,6 +4,9 @@
 #include "../lib/u_async.h"
 #include <stdlib.h>

+// Enable comprehensive debug output for loadbalancer module
+#define DEBUG_CATEGORY_LOADBALANCER 1
+
 // Forward declaration
 static void init_timeout_cb(void* arg);

@ -15,81 +18,147 @@ static void init_timeout_cb(void* arg);
 static uint64_t get_current_nanotime() {
    struct timespec ts;
    clock_gettime(CLOCK_MONOTONIC, &ts);
-    return (uint64_t)ts.tv_sec * 1000000000ULL + ts.tv_nsec;
+    uint64_t nanotime = (uint64_t)ts.tv_sec * 1000000000ULL + ts.tv_nsec;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "get_current_nanotime: tv_sec=%ld, tv_nsec=%ld, result=%llu",
+                ts.tv_sec, ts.tv_nsec, (unsigned long long)nanotime);
+    return nanotime;
 }

 // Select link for transmission (per spec)
 struct ETCP_LINK* etcp_loadbalancer_select_link(struct ETCP_CONN* etcp) {
-    if (!etcp || !etcp->links) return NULL;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: etcp=%p", etcp);
+    
+    if (!etcp || !etcp->links) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: invalid parameters (etcp=%p, links=%p)", 
+                  etcp, etcp ? etcp->links : NULL);
+        return NULL;
+    }
    
    struct ETCP_LINK* best = NULL;
    uint64_t min_load_time = UINT64_MAX;
+    uint64_t now_ns = get_current_nanotime();
+    uint64_t now_tb = now_ns / (TIMEBASE_NS / 10);  // To 0.1ms units
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: current time=%llu tb, scanning %d links", 
+                (unsigned long long)now_tb, etcp->links ? 1 : 0);
    
    struct ETCP_LINK* link = etcp->links;
+    int link_index = 0;
    while (link) {
+        link_index++;
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: evaluating link %d (%p) - initialized=%u, is_server=%u, bandwidth=%u",
+                    link_index, link, link->initialized, link->is_server, link->bandwidth);
+        
        if (!link->initialized) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d not initialized, checking if client connection needed",
+                        link_index);
            // Initiate connection if client
            if (!link->is_server && !link->init_timer) {
+                DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: initiating client connection for link %d", link_index);
                // Send INIT (via etcp_encrypt_send with special dgram)
                // Set timer
                link->init_timer = uasync_set_timeout(etcp->instance->ua, link->init_timeout, link, init_timeout_cb);  // Define cb
+                DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: set init timer for link %d", link_index);
            }
            link = link->next;
            continue;
        }
        
        // Update load time if inactive
-        uint64_t now_ns = get_current_nanotime();
-        uint64_t now_tb = now_ns / (TIMEBASE_NS / 10);  // To 0.1ms units
-        
        if (link->last_activity < now_tb - (DELTA_TIME_NS / (TIMEBASE_NS / 10))) {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d inactive, updating last_activity from %llu to %llu",
+                        link_index, (unsigned long long)link->last_activity, 
+                        (unsigned long long)(now_tb - (DELTA_TIME_NS / (TIMEBASE_NS / 10))));
            link->last_activity = now_tb - (DELTA_TIME_NS / (TIMEBASE_NS / 10));
        }
        
        // Check if can send (load time < now)
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d last_activity=%llu, now_tb=%llu",
+                    link_index, (unsigned long long)link->last_activity, (unsigned long long)now_tb);
+        
        if (link->last_activity < now_tb) {
+            DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d can send (load_time < now)", link_index);
            if (link->last_activity < min_load_time) {
+                DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d is better candidate (activity=%llu < %llu)",
+                            link_index, (unsigned long long)link->last_activity, (unsigned long long)min_load_time);
                min_load_time = link->last_activity;
                best = link;
            }
+        } else {
+            DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: link %d cannot send yet (load_time >= now)", link_index);
        }
        
        link = link->next;
    }
    
+    if (best) {
+        DEBUG_INFO(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: selected link %p (activity=%llu)", 
+                  best, (unsigned long long)min_load_time);
+    } else {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_select_link: no suitable link found");
+    }
+    
    return best;
 }

 // Init timeout callback (placeholder)
 static void init_timeout_cb(void* arg) {
-    struct ETCP_LINK* link = arg;
+    struct ETCP_LINK* link = (struct ETCP_LINK*)arg;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "init_timeout_cb: link=%p, retry_count=%u, timeout=%u", 
+                link, link->init_retry_count, link->init_timeout);
+    
    // Resend INIT, increment retry
    link->init_retry_count++;
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "init_timeout_cb: incremented retry_count to %u", link->init_retry_count);
+    
    if (link->init_retry_count > 5) {
+        DEBUG_ERROR(DEBUG_CATEGORY_ETCP, "init_timeout_cb: max retries exceeded (%u > 5), closing link", link->init_retry_count);
        // Fail
        etcp_link_close(link);
        return;
    }
+    
    // Resend...
    link->init_timeout *= 2;  // Backoff
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "init_timeout_cb: doubled timeout to %u ms", link->init_timeout);
    link->init_timer = uasync_set_timeout(link->etcp->instance->ua, link->init_timeout, link, init_timeout_cb);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "init_timeout_cb: rescheduled timer");
 }

 // Bandwidth limit update (called after send)
 void etcp_loadbalancer_update_after_send(struct ETCP_LINK* link, size_t pkt_size) {
-    if (!link || link->bandwidth == 0) return;
+    DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: link=%p, pkt_size=%zu", link, pkt_size);
+    
+    if (!link) {
+        DEBUG_WARN(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: called with NULL link");
+        return;
+    }
+    
+    if (link->bandwidth == 0) {
+        DEBUG_TRACE(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: link bandwidth is 0, skipping update");
+        return;
+    }
+    
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: link bandwidth=%u bits/sec, packet size=%zu bytes", 
+                link->bandwidth, pkt_size);
    
    // Time to transmit (ns)
    double byte_time_ns = 1000000000.0 / (link->bandwidth * 8.0);  // bits/sec to byte/ns
    uint64_t tx_time_ns = (uint64_t)(pkt_size * byte_time_ns);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: byte_time_ns=%.2f, tx_time_ns=%llu", 
+                byte_time_ns, (unsigned long long)tx_time_ns);
    
    // To timebase (0.1ms units)
    uint64_t tx_time_tb = tx_time_ns / (TIMEBASE_NS / 10);
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: tx_time_tb=%llu", (unsigned long long)tx_time_tb);
    
    // Update last_activity
    uint64_t now_tb = get_current_nanotime() / (TIMEBASE_NS / 10);
+    uint64_t old_activity = link->last_activity;
    link->last_activity += tx_time_tb;
    if (link->last_activity < now_tb - (DELTA_TIME_NS / (TIMEBASE_NS / 10))) {
        link->last_activity = now_tb - (DELTA_TIME_NS / (TIMEBASE_NS / 10));
    }
+    DEBUG_DEBUG(DEBUG_CATEGORY_ETCP, "etcp_loadbalancer_update_after_send: updated last_activity from %llu to %llu", 
+                (unsigned long long)old_activity, (unsigned long long)link->last_activity);
 }
--- a/test_debug.conf
+++ b/test_debug.conf
@ -1,3 +0,0 @@
-[global]
-my_node_id=0x1111111111111111
-my_private_key=1313912e5d34768983b0e06530a48c77816d228a5b5605e1ab3dc443d107a3dc
--- a/test_debug_demo.sh
+++ b/test_debug_demo.sh
@ -0,0 +1,70 @@
+#!/bin/bash
+# Test script to demonstrate ETCP debug output
+
+echo "=== Testing ETCP Debug Output ==="
+echo "This script demonstrates the comprehensive debug output added to ETCP and loadbalancer modules"
+echo ""
+
+echo "1. Testing with ETCP debug output enabled:"
+echo "   Command: ./src/utun -d 'etcp:debug' --help"
+echo ""
+
+# Create a minimal config for testing
+cat > test_debug.conf << EOF
+[instance]
+node_id = 0x1122334455667788
+priv_key = 67b705a92b41bcaae105af2d6a17743faa7b26ccebba8b3b9b0af05e9cd1d5fb
+pub_key = 1c55e4ccae7c4470707759086738b10681bf88b81f198cc2ab54a647d1556e17c65e6b1833e0c771e5a39382c03067c388915a4c732191bc130480f20f8e00b9
+
+[tun]
+ip = 10.0.0.1
+port = 1234
+
+[peer]
+node_id = 0x8877665544332211
+ip = 127.0.0.1
+port = 1235
+pub_key = 1c55e4ccae7c4470707759086738b10681bf88b81f198cc2ab54a647d1556e17c65e6b1833e0c771e5a39382c03067c388915a4c732191bc130480f20f8e00b9
+EOF
+
+echo "2. Configuration file created for testing"
+echo ""
+
+echo "3. Available debug levels:"
+echo "   - etcp:trace    - Most detailed output (function entry/exit, packet details)"
+echo "   - etcp:debug    - Detailed operational info (packet processing, state changes)"
+echo "   - etcp:info     - Important events (connections, errors)"
+echo "   - etcp:warn     - Warnings only"
+echo "   - etcp:error    - Errors only"
+echo ""
+
+echo "4. Example debug configurations:"
+echo "   -d 'etcp:trace'                    # Maximum ETCP detail"
+echo "   -d 'etcp:debug,loadbalancer:debug' # ETCP + loadbalancer detail"
+echo "   -d 'etcp:info,timing:debug'        # ETCP info + timing detail"
+echo "   -d 'all:debug'                      # Everything at debug level"
+echo ""
+
+echo "5. Key debug areas covered:"
+echo "   ✓ Connection creation/destruction"
+echo "   ✓ Packet transmission and reception"
+echo "   ✓ ACK processing and retransmission"
+echo "   ✓ RTT calculation and jitter analysis"
+echo "   ✓ Load balancer link selection"
+echo "   ✓ Bandwidth measurement and updates"
+echo "   ✓ Gap detection and packet delivery"
+echo "   ✓ Timer operations (retransmission, ACK)"
+echo "   ✓ Memory management (allocation/free)"
+echo ""
+
+echo "6. To see debug output in action, run:"
+echo "   ./src/utun -c test_debug.conf -d 'etcp:trace,loadbalancer:trace' -f"
+echo ""
+
+echo "=== Debug Output Summary ==="
+echo "The ETCP and loadbalancer modules now have comprehensive debug output using the DEBUG_* macros."
+echo "This will help you trace every operation, packet flow, timing calculation, and state change."
+echo ""
+
+# Clean up
+rm -f test_debug.conf