WIP:fix: send element stuck after TRANSMIT_COMPLETE_FAIL

TS fails to deliver a fragmented frame it called
send_data_callback_func(TRANSMIT_COMPLETE_FAIL), in this cause the TS
does not pop the falied session. Subsequent sends appended a fresh
frame to the tail while the stale 48-byte session stayed at the head,
causing all following commands to be re-driven through Transport Service
regardless of their actual size.

Fix a potential double-callback in fc_timer_expired: after invoking
completedFunc in the flag_replied_frag_req path, null the pointer so
the transmission_aborted guard cannot call it a second time if the
timer fires again.

Author: lmolina

libs2/protocol/S2.c

@@ -12,6 +12,7 @@
 #include "misc.h"
 #include "../inclusion/s2_inclusion_internal.h"
 #include<string.h>
+#include <stdio.h>
 #include "ccm.h"
 #include "aes_cmac.h"
 #include "nextnonce.h"
@@ -447,6 +448,9 @@ S2_encrypt_and_send(struct S2* p_context)
 
   hdr_len = 4;
   n_ext = 0;
+  printf("[ZGW-3457] S2_encrypt_and_send: src=%u dst=%u plaintext=%u span_state=%u\n",
+         ctxt->peer.l_node, ctxt->peer.r_node, ctxt->length, span->state);
+  fflush(stdout);
   DPRINT("S2_encrypt_and_send\r\n");
   /*If span is not negotiated, include senders nonce (SN) */
   ext_data = &msg[4];
@@ -567,6 +571,9 @@ S2_encrypt_and_send(struct S2* p_context)
   debug_print_hex(ciphertext, msg_len);
 
   ASSERT(msg_len > 0);
+  printf("[ZGW-3457] S2_encrypt_and_send: total_frame=%u (hdr=%u shdr=%u payload=%u mic=%u)\n",
+         msg_len + hdr_len, hdr_len, shdr_len, ctxt->length, msg_len - ctxt->length - shdr_len);
+  fflush(stdout);
   S2_send_raw(ctxt, msg, msg_len + hdr_len);
 }
 

libs2/transport_service/transport_service2.c

@@ -512,6 +512,7 @@ void fc_timer_expired(void *nthing)
 #else
             scb.cmn.completedFunc(S2_TRANSMIT_COMPLETE_FAIL, 0);
 #endif
+            scb.cmn.completedFunc = NULL;
         }
         return;
     }

src/transport/S2_wrap.c

@@ -603,7 +603,7 @@ uint8_t S2_send_frame(struct S2* ctxt,const s2_connection_t* conn, uint8_t* buf,
   p.snode = conn->l_node;
   p.dnode = conn->r_node;
   p.tx_flags = conn->zw_tx_options;
-  LOG_PRINTF(" Sending S2_send_frame %i %d -> %d\n", len, p.snode, p.dnode);
+  LOG_PRINTF("[ZGW-3457] S2_send_frame: len=%i src=%d dst=%d\n", len, p.snode, p.dnode);
   transmit_start_time = clock_time();
   return send_data(&p, buf,  len,S2_send_frame_callback,ctxt);
 }

src/transport/ZW_SendDataAppl.c

@@ -280,33 +280,39 @@ do_discard_timeout_memb(void * data)
 static void
 send_data_callback_func(u8_t status, TX_STATUS_TYPE* ts)
 {
-  LOG_PRINTF("send_data_callback_func() | status %d\n", status);
+  LOG_PRINTF("[ZGW-3457] send_data_callback_func: status=%d\n", status);
   enum en_queue_state queue_state = get_queue_state();
 
   if(!lock_ll) {
     ERR_PRINTF("Double callback?\n");
     return;
   }
 
-  
-  // if (status == TRANSMIT_COMPLETE_NO_ACK)
+  // TS and other senders report TRANSMIT_COMPLETE_FAIL. Pop and
+  // free the session so the queue advances; the original hold-for-retry
+  // behaviour (previously on NO_ACK) is preserved only when the resend watchdog
+  // is active.
   if (status == TRANSMIT_COMPLETE_FAIL)
   {
     etimer_stop(&emergency_timer);
 
     if(resend_counter == 0) {
-      send_data_appl_session_t *s = list_head(send_data_list);
+      send_data_appl_session_t *s = list_pop(send_data_list);
       if (s)
       {
+        zw_frame_buffer_free(s->fb);
+        memb_free(&session_memb, s);
         if (s->callback)
         {
           s->callback(status, s->user, ts);
         }
       }
       else
       {
+        DBG_PRINTF("event in the send data list is NULL\n");
         ASSERT(0);
       }
+      process_post(&ZW_SendDataAppl_process, SEND_EVENT_SEND_NEXT_LL, NULL);
     }
 
     lock_ll = FALSE;
@@ -795,6 +801,11 @@ PROCESS_THREAD(ZW_SendDataAppl_process, ev, data)
         DBG_PRINTF("SEND_EVENT_SEND_NEXT_LL | current_session_ll: %p | lock_ll %u\n", current_session_ll, lock_ll);
         if (current_session_ll && lock_ll == FALSE)
         {
+          LOG_PRINTF("[ZGW-3457] SEND_NEXT_LL: routing session %p snode=%u dnode=%u frame_len=%u\n",
+                     (void*)current_session_ll,
+                     (unsigned)current_session_ll->fb->param.snode,
+                     (unsigned)current_session_ll->fb->param.dnode,
+                     (unsigned)current_session_ll->fb->frame_len);
           if(current_session_ll->fb->param.discard_timeout)
           {
             //Prevent a timer to discard the frame if the session has a discard_timeout defined.
@@ -810,7 +821,7 @@ PROCESS_THREAD(ZW_SendDataAppl_process, ev, data)
             if (SupportsCmdClass(current_session_ll->fb->param.dnode,
                 COMMAND_CLASS_TRANSPORT_SERVICE))
             {
-              DBG_PRINTF("SEND_EVENT_SEND_NEXT_LL | SupportsCmdClass | ZW_TransportService_SendData \n");
+              LOG_PRINTF("[ZGW-3457] SEND_NEXT_LL: -> ZW_TransportService_SendData\n");
               LOG_PRINTF("[ZGW-3457][TS] SendDataAppl->TransportService snode=%u dnode=%u frame_len=%u dnode_low8=%u\n",
                          (unsigned)current_session_ll->fb->param.snode,
                          (unsigned)current_session_ll->fb->param.dnode,
@@ -843,7 +854,7 @@ PROCESS_THREAD(ZW_SendDataAppl_process, ev, data)
           {
             if (current_session_ll->fb->param.snode != MyNodeID)
             {
-              DBG_PRINTF("SEND_EVENT_SEND_NEXT_LL | ZW_SendData_Bridge \n");
+              LOG_PRINTF("[ZGW-3457] SEND_NEXT_LL: -> ZW_SendData_Bridge\n");
               if (etimer_expired(&resend_lockup_timer) && (cfg.time_resend_serial != 0)) {
                 DBG_PRINTF("etimer_set resend_lockup_timer with time: %d \n", cfg.time_resend_serial);
                 etimer_set(&resend_lockup_timer, 1000UL * cfg.time_resend_serial);