Timings seems to be OK, (to be checked more accurately)

openair3/TEST/EPC_TEST/play_scenario.h

@@ -344,11 +344,11 @@ typedef struct et_scenario_s {
 
   hash_table_t           *hash_mme2association_id;
   hash_table_t           *hash_old_ue_mme_id2ue_mme_id;
-  struct timeval          time_last_tx_packet;
-  struct timeval          time_last_rx_packet;
-  et_packet_t            *last_rx_packet;         // last packet received with all previous scenario RX packet received.
-  et_packet_t            *last_tx_packet;         // last sent packet
-  et_packet_t            *next_packet;   // next packet to be handled in the scenario (RX or TX packet)
+  struct timeval          time_last_tx_packet;    // Time last sent packet
+  struct timeval          time_last_rx_packet;    // Time last packet received with all previous scenario RX packet received.
+  et_packet_t            *last_rx_packet;         // Last packet received with all previous scenario RX packet received.
+  et_packet_t            *last_tx_packet;         // Last sent packet
+  et_packet_t            *next_packet;            // Next packet to be handled in the scenario (RX or TX packet)
 } et_scenario_t;
 
 

openair3/TEST/EPC_TEST/play_scenario_fsm.c

@@ -55,17 +55,19 @@ uint32_t          g_constraints = ET_BIT_MASK_MATCH_SCTP_STREAM | ET_BIT_MASK_MA
 int timeval_subtract (struct timeval * const result, struct timeval * const a, struct timeval * const b)
 {
   struct timeval  b2;
+  int nsec = 0;
   b2.tv_sec   = b->tv_sec;
   b2.tv_usec = b->tv_usec;
 
+
   /* Perform the carry for the later subtraction by updating y. */
   if (a->tv_usec < b2.tv_usec) {
-    int nsec = (b2.tv_usec - a->tv_usec) / 1000000 + 1;
+    nsec = (b2.tv_usec - a->tv_usec) / 1000000 + 1;
     b2.tv_usec -= 1000000 * nsec;
     b2.tv_sec += nsec;
   }
   if (a->tv_usec - b2.tv_usec > 1000000) {
-    int nsec = (a->tv_usec - b2.tv_usec) / 1000000;
+    nsec = (a->tv_usec - b2.tv_usec) / 1000000;
     b2.tv_usec += 1000000 * nsec;
     b2.tv_sec -= nsec;
   }
@@ -75,7 +77,8 @@ int timeval_subtract (struct timeval * const result, struct timeval * const a, s
   result->tv_sec = a->tv_sec - b2.tv_sec;
   result->tv_usec = a->tv_usec - b2.tv_usec;
 
-  /* Return 1 if result is negative. */
+  LOG_D(ENB_APP, "timeval_subtract(%ld.%06d, %ld.%06d)=%ld.%06d\n", a->tv_sec, a->tv_usec, b->tv_sec, b->tv_usec, result->tv_sec, result->tv_usec);
+
   return a->tv_sec < b2.tv_sec;
 }
 
@@ -117,15 +120,22 @@ void et_scenario_schedule_tx_packet(et_packet_t * const packet)
       AssertFatal(gettimeofday(&now, NULL) == 0, "gettimeofday failed");
       timeval_subtract(&offset_last_tx_packet,&now,&g_scenario->time_last_tx_packet);
       timeval_subtract(&offset_last_rx_packet,&now,&g_scenario->time_last_rx_packet);
+      LOG_D(ENB_APP, "offset_last_tx_packet=%ld.%06d\n", offset_last_tx_packet.tv_sec, offset_last_tx_packet.tv_usec);
+      LOG_D(ENB_APP, "offset_last_rx_packet=%ld.%06d\n", offset_last_rx_packet.tv_sec, offset_last_rx_packet.tv_usec);
+
       last_packet_was_tx = timeval_subtract(&offset_tx_rx,&offset_last_tx_packet,&offset_last_rx_packet);
       if (last_packet_was_tx) {
+        LOG_D(ENB_APP, "last_packet_was_tx\n");
         we_are_too_early = timeval_subtract(&offset,&offset_last_tx_packet,&packet->time_relative_to_last_sent_packet);
+        LOG_D(ENB_APP, "we_are_too_early=%d, offset=%ld.%06d\n", we_are_too_early, offset.tv_sec, offset.tv_usec);
       } else {
+        LOG_D(ENB_APP, "last_packet_was_rx\n");
         we_are_too_early = timeval_subtract(&offset,&offset_last_rx_packet,&packet->time_relative_to_last_received_packet);
+        LOG_D(ENB_APP, "we_are_too_early=%d, offset=%ld.%06d\n", we_are_too_early, offset.tv_sec, offset.tv_usec);
       }
       if (we_are_too_early > 0) {
         // set timer
-        LOG_D(ENB_APP, "Send packet num %u original frame number %u in %ld.%d sec\n",
+        LOG_D(ENB_APP, "Send packet num %u original frame number %u in %ld.%06d sec\n",
             packet->packet_number, packet->original_frame_number, offset.tv_sec, offset.tv_usec);
 
         packet->status = ET_PACKET_STATUS_SCHEDULED_FOR_SENDING;
@@ -138,6 +148,10 @@ void et_scenario_schedule_tx_packet(et_packet_t * const packet)
         LOG_D(ENB_APP, "Send packet num %u original frame number %u immediately\n", packet->packet_number, packet->original_frame_number);
         // send immediately
         AssertFatal(0 == gettimeofday(&packet->timestamp_packet, NULL), "gettimeofday() Failed");
+
+        g_scenario->time_last_tx_packet.tv_sec  = packet->timestamp_packet.tv_sec;
+        g_scenario->time_last_tx_packet.tv_usec = packet->timestamp_packet.tv_usec;
+
         et_s1ap_eNB_itti_send_sctp_data_req(
             packet->enb_instance,
             packet->sctp_hdr.u.data_hdr.assoc_id,
@@ -266,6 +280,10 @@ et_fsm_state_t et_scenario_fsm_notify_event_state_waiting_tx(et_event_t event)
     case ET_EVENT_TX_TIMED_PACKET:
       // send immediately
       AssertFatal(0 == gettimeofday(&event.u.tx_timed_packet->timestamp_packet, NULL), "gettimeofday() Failed");
+
+      g_scenario->time_last_tx_packet.tv_sec  = event.u.tx_timed_packet->timestamp_packet.tv_sec;
+      g_scenario->time_last_tx_packet.tv_usec = event.u.tx_timed_packet->timestamp_packet.tv_usec;
+
       et_s1ap_eNB_itti_send_sctp_data_req(
           event.u.tx_timed_packet->enb_instance,
           event.u.tx_timed_packet->sctp_hdr.u.data_hdr.assoc_id,
@@ -325,8 +343,7 @@ et_fsm_state_t et_scenario_fsm_notify_event_state_connecting_s1c(et_event_t even
       break;
 
     case ET_EVENT_S1C_CONNECTED:
-      // hack simulate we have been able to get the right timing values
-      AssertFatal(gettimeofday(&g_scenario->time_last_tx_packet, NULL) == 0, "gettimeofday failed");
+      // hack simulate we have been able to get the right timing values for STCP connect
       AssertFatal(gettimeofday(&g_scenario->time_last_rx_packet, NULL) == 0, "gettimeofday failed");
 
       while (NULL != g_scenario->next_packet) {
@@ -452,6 +469,7 @@ et_fsm_state_t et_scenario_fsm_notify_event_state_null(et_event_t event)
             // Try to register each eNB
             g_scenario->registered_enb       = 0;
             g_fsm_state            = ET_FSM_STATE_CONNECTING_S1C;
+            AssertFatal(gettimeofday(&g_scenario->time_last_tx_packet, NULL) == 0, "gettimeofday failed");
             et_eNB_app_register (g_scenario->enb_properties);
             pthread_mutex_unlock(&g_fsm_lock);
             return g_fsm_state;

openair3/TEST/EPC_TEST/play_scenario_parse.c

@@ -343,6 +343,7 @@ et_packet_t* et_parse_xml_packet(xmlDocPtr doc, xmlNodePtr node) {
 
     xml_char = xmlGetProp(node, (const xmlChar *)"action");
     packet->action = et_action_str2et_action_t(xml_char);
+    packet->status = ET_PACKET_STATUS_NONE;
     xmlFree(xml_char);
     packet->packet_number = packet_number++;
 

openair3/TEST/EPC_TEST/play_scenario_s1ap.c

@@ -254,13 +254,18 @@ int et_scenario_set_packet_received(et_packet_t * const packet)
   int           rc = 0;
 
   packet->status = ET_PACKET_STATUS_RECEIVED;
-  S1AP_DEBUG("Packet num %d received\n", packet->packet_number);
+  S1AP_DEBUG("Packet received:          num %u  | original frame number %u \n", packet->packet_number, packet->original_frame_number);
+  S1AP_DEBUG("Last Packet received:     num %u  | original frame number %u \n", g_scenario->last_rx_packet->packet_number, g_scenario->last_rx_packet->original_frame_number);
 
   p = g_scenario->last_rx_packet;
   while (NULL != p) {
-    if (p->action == ET_PACKET_ACTION_S1C_RECEIVE) {
-      if (p->status == ET_PACKET_STATUS_RECEIVED) {
+    if (ET_PACKET_ACTION_S1C_RECEIVE == p->action) {
+      if ((ET_PACKET_STATUS_RECEIVED == p->status) || (ET_PACKET_STATUS_NOT_TAKEN_IN_ACCOUNT == p->status)) {
         g_scenario->last_rx_packet = p;
+        g_scenario->time_last_rx_packet.tv_sec   = p->timestamp_packet.tv_sec;
+        g_scenario->time_last_rx_packet.tv_usec  = p->timestamp_packet.tv_usec;
+        S1AP_DEBUG("Set Last Packet received: num %u  | original frame number %u \n", g_scenario->last_rx_packet->packet_number, g_scenario->last_rx_packet->original_frame_number);
+        S1AP_DEBUG("Set time_last_rx_packet %ld.%06d\n", g_scenario->time_last_rx_packet.tv_sec, g_scenario->time_last_rx_packet.tv_usec);
       } else {
         break;
       }
@@ -268,7 +273,7 @@ int et_scenario_set_packet_received(et_packet_t * const packet)
     p = p->next;
   }
 
-  if (packet->timer_id != 0) {
+  if (0 != packet->timer_id) {
     rc = timer_remove(packet->timer_id);
     AssertFatal(rc == 0, "TODO: Debug Timer on Rx packet num %d unknown", packet->packet_number);
     return rc;
@@ -291,9 +296,14 @@ int et_s1ap_process_rx_packet(et_event_s1ap_data_ind_t * const s1ap_data_ind)
     packet = g_scenario->list_packet;
     while (NULL != packet) {
       if (packet->action == ET_PACKET_ACTION_S1C_RECEIVE) {
-        if (packet->status == ET_PACKET_STATUS_RECEIVED) {
+        if ((ET_PACKET_STATUS_RECEIVED == packet->status) || (ET_PACKET_STATUS_NOT_TAKEN_IN_ACCOUNT == packet->status)) {
           g_scenario->last_rx_packet = packet;
-          g_scenario->time_last_rx_packet = g_scenario->last_rx_packet->timestamp_packet;
+          if  (ET_PACKET_STATUS_NOT_TAKEN_IN_ACCOUNT != packet->status) {
+            g_scenario->time_last_rx_packet.tv_sec  = packet->timestamp_packet.tv_sec;
+            g_scenario->time_last_rx_packet.tv_usec = packet->timestamp_packet.tv_usec;
+          }
+          S1AP_DEBUG("Set Last Packet received: num %u  | original frame number %u \n", g_scenario->last_rx_packet->packet_number, g_scenario->last_rx_packet->original_frame_number);
+          S1AP_DEBUG("Set time_last_rx_packet %ld.%06d\n", g_scenario->time_last_rx_packet.tv_sec, g_scenario->time_last_rx_packet.tv_usec);
         } else {
           break;
         }
@@ -309,10 +319,13 @@ int et_s1ap_process_rx_packet(et_event_s1ap_data_ind_t * const s1ap_data_ind)
     if (packet->action == ET_PACKET_ACTION_S1C_RECEIVE) {
       rv = et_sctp_is_matching(&packet->sctp_hdr, &rx_packet->sctp_hdr, g_constraints);
       if (0 == rv) {
-        S1AP_DEBUG("Compare RX packet with packet num %d succeeded\n", packet->packet_number);
+        S1AP_DEBUG("Compare RX packet with packet: num %u  | original frame number %u \n", packet->packet_number, packet->original_frame_number);
+        packet->timestamp_packet.tv_sec = rx_packet->timestamp_packet.tv_sec;
+        packet->timestamp_packet.tv_usec = rx_packet->timestamp_packet.tv_usec;
         return et_scenario_set_packet_received(packet);
       } else {
-        S1AP_DEBUG("Compare RX packet with packet num %d failed %s\n", packet->packet_number, et_error_match2str(rv));
+        S1AP_DEBUG("Compare RX packet with packet: num %u  | original frame number %u failed:%s\n",
+            packet->packet_number, packet->original_frame_number, et_error_match2str(rv));
         // asn1 compare no match return code, may not collide with non asn1 error return codes
         // (each asn1 rc <= 166 (enum e_S1ap_ProtocolIE_ID, in generated file S1ap_ProtocolIE_ID.h))
         if ((rv > 0) || (rv <= -ET_ERROR_MATCH_END)) {