logs

These calls provide additional information about cell and UE RNTI.

openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_dlsch.c

@@ -347,7 +347,7 @@ static void nr_store_dlsch_buffer(module_id_t module_id, frame_t frame, slot_t s
 
       sched_ctrl->dl_pdus_total += sched_ctrl->rlc_status[lcid].pdus_in_buffer;
       sched_ctrl->num_total_bytes += sched_ctrl->rlc_status[lcid].bytes_in_buffer;
-      LOG_D(MAC,
+      LOG_I(MAC,
             "[gNB %d][%4d.%2d] %s%d->DLSCH, RLC status for UE %d: %d bytes in buffer, total DL buffer size = %d bytes, %d total PDU bytes, %s TA command\n",
             module_id,
             frame,
@@ -1097,7 +1097,7 @@ void nr_schedule_ue_spec(module_id_t module_id,
       harq->is_waiting = true;
     }
     UE->mac_stats.dl.rounds[harq->round]++;
-    LOG_D(NR_MAC,
+    LOG_I(NR_MAC,
           "%4d.%2d [DLSCH/PDSCH/PUCCH] RNTI %04x DCI L %d start %3d RBs %3d startSymbol %2d nb_symbol %2d dmrspos %x MCS %2d nrOfLayers %d TBS %4d HARQ PID %2d round %d RV %d NDI %d dl_data_to_ULACK %d (%d.%d) PUCCH allocation %d TPC %d\n",
           frame,
           slot,

openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_primitives.c

@@ -3461,11 +3461,10 @@ void nr_measgap_scheduling(gNB_MAC_INST *nr_mac, frame_t frame, sub_frame_t slot
       continue;
 
     NR_timer_t *t = &UE->UE_sched_ctrl.transm_interrupt;
-    interrupt_followup_action_t a = nr_timer_is_active(t) ? UE->interrupt_action : FOLLOW_INSYNC;
     // start a timer to stop scheduling UE during MeasGap, or extend timer for
     // duration of measGap with existing follow-up action
     if (!nr_timer_is_active(t) || nr_timer_remaining_time(t) < mgc->mgl_slots) {
-      nr_mac_interrupt_ue_transmission(nr_mac, UE, a, mgc->mgl_slots);
+      nr_mac_interrupt_ue_transmission(nr_mac, UE, mgc->mgl_slots);
     }
   }
 }
@@ -3549,7 +3548,7 @@ int nr_mac_get_reconfig_delay_slots(NR_SubcarrierSpacing_t scs)
   return (delay_ms << scs) + sl_ahead;
 }
 
-int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, interrupt_followup_action_t action, int slots)
+int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, int slots)
 {
   DevAssert(mac != NULL);
   DevAssert(UE != NULL);
@@ -3557,7 +3556,6 @@ int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, interr
 
   nr_timer_setup(&UE->UE_sched_ctrl.transm_interrupt, slots, 1);
   nr_timer_start(&UE->UE_sched_ctrl.transm_interrupt);
-  UE->interrupt_action = action;
 
   // it might happen that timing advance command should be sent during the UE
   // inactivity time. To prevent this, set a variable as if we would have just
@@ -3565,14 +3563,27 @@ int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, interr
   // frames, after the inactivity of the UE.
   UE->UE_sched_ctrl.ta_frame = (mac->frame - 1 + 1024) % 1024;
 
-  LOG_D(NR_MAC, "UE %04x: Interrupt UE transmission (%d slots) action %d\n", UE->rnti, slots, UE->interrupt_action);
+  LOG_I(NR_MAC, "UE %04x: Interrupt UE transmission (%d slots)\n", UE->rnti, slots);
   return 0;
 }
 
+static void nr_mac_ue_transmission_timeout(gNB_MAC_INST *mac, NR_UE_info_t *UE, int slots)
+{
+  DevAssert(mac != NULL);
+  DevAssert(UE != NULL);
+  NR_SCHED_ENSURE_LOCKED(&mac->sched_lock);
+
+  nr_timer_setup(&UE->UE_sched_ctrl.transm_timeout, slots, 1);
+  nr_timer_start(&UE->UE_sched_ctrl.transm_timeout);
+
+  LOG_I(NR_MAC, "UE %04x: Timeout for UE transmission (%d slots)\n", UE->rnti, slots);
+  return;
+}
+
 int nr_transmission_action_indicator_stop(gNB_MAC_INST *mac, NR_UE_info_t *UE_info)
 {
   int delay = nr_mac_get_reconfig_delay_slots(UE_info->current_DL_BWP.scs);
-  nr_mac_interrupt_ue_transmission(mac, UE_info, FOLLOW_OUTOFSYNC, delay);
+  nr_mac_ue_transmission_timeout(mac, UE_info, delay);
   LOG_I(NR_MAC, "gNB-DU received the TransmissionActionIndicator with Stop value for UE %04x\n", UE_info->rnti);
   return 0;
 }
@@ -3641,9 +3652,11 @@ void nr_mac_update_timers(module_id_t module_id, frame_t frame, slot_t slot)
     if (nr_timer_tick(&sched_ctrl->transm_interrupt)) {
       /* expired */
       nr_timer_stop(&sched_ctrl->transm_interrupt);
-      if (UE->interrupt_action == FOLLOW_OUTOFSYNC)
-        nr_mac_trigger_ul_failure(sched_ctrl, UE->current_DL_BWP.scs);
-      /* else: default FOLLOW_INSYNC: nothing to do (UE is now active again) */
+    }
+    if (nr_timer_tick(&sched_ctrl->transm_timeout)) {
+      nr_timer_stop(&sched_ctrl->transm_timeout);
+      LOG_W(NR_MAC, "UE %04x UL failure after transmission timeout\n", UE->rnti);
+      nr_mac_trigger_ul_failure(sched_ctrl, UE->current_DL_BWP.scs);
     }
   }
 }

openair2/LAYER2/NR_MAC_gNB/mac_proto.h

@@ -65,7 +65,7 @@ void nr_mac_prepare_ra_ue(gNB_MAC_INST *nrmac, NR_UE_info_t *UE);
 bool add_new_UE_RA(gNB_MAC_INST *nr_mac, NR_UE_info_t *UE);
 int nr_mac_get_reconfig_delay_slots(NR_SubcarrierSpacing_t scs);
 
-int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, interrupt_followup_action_t action, int slots);
+int nr_mac_interrupt_ue_transmission(gNB_MAC_INST *mac, NR_UE_info_t *UE, int slots);
 int nr_transmission_action_indicator_stop(gNB_MAC_INST *mac, NR_UE_info_t *UE_info);
 
 void clear_nr_nfapi_information(gNB_MAC_INST *gNB,

openair2/LAYER2/NR_MAC_gNB/mac_rrc_dl_handler.c

@@ -764,6 +764,7 @@ void ue_context_modification_request(const f1ap_ue_context_mod_req_t *req)
 
   if (req->rrc_container != NULL) {
     logical_chan_id_t id = 1;
+    LOG_W(NR_MAC, "forwarding UE %d bytes %ld\n", req->gNB_DU_ue_id, req->rrc_container->len);
     nr_rlc_srb_recv_sdu(req->gNB_DU_ue_id, id, req->rrc_container->buf, req->rrc_container->len);
   }
 

openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h

@@ -688,6 +688,10 @@ typedef struct {
   /// Timer for RRC processing procedures and transmission activity
   NR_timer_t transm_interrupt;
 
+  /// Timer for timeout before UE is set to UL failure (e.g.,
+  /// "TransmissionActionIndicator" handling
+  NR_timer_t transm_timeout;
+
   /// sri, ul_ri and tpmi based on SRS
   nr_srs_feedback_t srs_feedback;
 
@@ -762,8 +766,6 @@ typedef struct measgap_config {
   int mgl_slots;
 } measgap_config_t;
 
-typedef enum interrupt_followup_action { FOLLOW_INSYNC, FOLLOW_OUTOFSYNC } interrupt_followup_action_t;
-
 /*! \brief UE list used by gNB to order UEs/CC for scheduling*/
 typedef struct {
   rnti_t rnti;
@@ -780,7 +782,6 @@ typedef struct {
   /// in case of reestablishment, old spCellConfig to apply after
   /// reconfiguration
   NR_SpCellConfig_t *reconfigSpCellConfig;
-  interrupt_followup_action_t interrupt_action;
   NR_UE_NR_Capability_t *capability;
   measgap_config_t measgap_config;
   // UE selected beam index

openair2/RRC/NR/rrc_gNB.c

@@ -1279,6 +1279,8 @@ static void rrc_handle_RRCReestablishmentRequest(gNB_RRC_INST *rrc,
   }
   gNB_RRC_UE_t *UE = &ue_context_p->ue_context;
 
+  LOG_UE_UL_EVENT(UE, "RRCReestablishmentRequest\n");
+
   /* should check phys cell ID to identify the correct cell */
   const f1ap_served_cell_info_t *cell_info = &du->setup_req->cell[0].info;
   const f1ap_served_cell_info_t *previous_cell_info = get_cell_information_by_phycellId(physCellId);
@@ -1292,24 +1294,7 @@ static void rrc_handle_RRCReestablishmentRequest(gNB_RRC_INST *rrc,
      * target DU and and update the association to the initial DU one */
     LOG_W(NR_RRC, "handover for UE %d/RNTI %04x failed, rollback to original cell\n", UE->rrc_ue_id, UE->rnti);
 
-    // find the transaction of handover (the corresponding reconfig) and abort it
-    for (int i = 0; i < NR_RRC_TRANSACTION_IDENTIFIER_NUMBER; ++i) {
-      if (UE->xids[i] == RRC_DEDICATED_RECONF)
-        UE->xids[i] = RRC_ACTION_NONE;
-    }
-
     source_ctx->ho_cancel(rrc, UE);
-
-    /* we need the original CellGroupConfig */
-    ASN_STRUCT_FREE(asn_DEF_NR_CellGroupConfig, UE->masterCellGroup);
-    UE->masterCellGroup = source_ctx->old_cellGroupConfig;
-    source_ctx->old_cellGroupConfig = NULL;
-
-    /* update to old DU assoc id -- RNTI + secondary DU UE ID further below */
-    f1_ue_data_t ue_data = cu_get_f1_ue_data(UE->rrc_ue_id);
-    ue_data.du_assoc_id = source_ctx->du->assoc_id;
-    bool success = cu_update_f1_ue_data(UE->rrc_ue_id, &ue_data);
-    DevAssert(success);
     nr_rrc_finalize_ho(UE);
   } else if (physCellId != cell_info->nr_pci) {
     /* UE was moving from previous cell so quickly that RRCReestablishment for previous cell was received in this cell */
@@ -2339,7 +2324,7 @@ static void rrc_CU_process_ue_context_modification_response(MessageDef *msg_p, i
     ue_data.du_assoc_id = target_ctx->du->assoc_id;
     bool success = cu_update_f1_ue_data(UE->rrc_ue_id, &ue_data);
     DevAssert(success);
-    LOG_I(NR_RRC, "UE %d handover: update RNTI from %04x to %04x\n", UE->rrc_ue_id, UE->rnti, target_ctx->new_rnti);
+    LOG_UE_EVENT(UE, "Handover: update RNTI from %04x to %04x\n", UE->rnti, target_ctx->new_rnti);
     nr_ho_source_cu_t *source_ctx = UE->ho_context->source;
     DevAssert(source_ctx->old_rnti == UE->rnti);
     UE->rnti = target_ctx->new_rnti;
@@ -2365,17 +2350,25 @@ static void rrc_CU_process_ue_modification_required(MessageDef *msg_p, instance_
   }
 
   gNB_RRC_UE_t *UE = &ue_context_p->ue_context;
-  if (UE->ho_context && UE->ho_context->source && UE->ho_context->source->du && UE->ho_context->source->du->assoc_id == assoc_id) {
-    LOG_W(NR_RRC, "UE %d: UE Context Modification Required during handover, ignoring message\n", UE->rrc_ue_id);
-    return;
+  if (UE->ho_context) {
+    if (UE->ho_context->target && UE->ho_context->target->du && UE->ho_context->target->du->assoc_id == assoc_id) {
+      LOG_A(NR_RRC, "UE %d: UE Context Modification Required during handover on target DU, handover succeeded\n", UE->rrc_ue_id);
+      UE->ho_context->target->ho_success(rrc, UE);
+    } else if (UE->ho_context->source) {
+      if (UE->ho_context->source->du && UE->ho_context->source->du->assoc_id == assoc_id)
+        LOG_W(NR_RRC, "UE %d: UE Context Modification Required during handover on source DU, handover failed\n", UE->rrc_ue_id);
+      else
+        LOG_W(NR_RRC, "UE %d: UE Context Modification Required, unknown or no source DU\n", UE->rrc_ue_id);
+      UE->ho_context->source->ho_cancel(rrc, UE);
+    } else {
+      LOG_E(NR_RRC, "UE %d: UE Context Modification Required during handover: unhandled case\n", UE->rrc_ue_id);
+    }
+    nr_rrc_finalize_ho(UE);
   }
 
   if (required->du_to_cu_rrc_information && required->du_to_cu_rrc_information->cellGroupConfig) {
     gNB_RRC_UE_t *UE = &ue_context_p->ue_context;
-    LOG_I(RRC,
-          "UE Context Modification Required: new CellGroupConfig for UE ID %d/RNTI %04x, triggering reconfiguration\n",
-          UE->rrc_ue_id,
-          UE->rnti);
+    LOG_UE_UL_EVENT(UE, "UE Context Modification Required: new CellGroupConfig, triggering reconfiguration\n");
 
     NR_CellGroupConfig_t *cellGroupConfig = NULL;
     asn_dec_rval_t dec_rval = uper_decode_complete(NULL,
@@ -2406,6 +2399,8 @@ static void rrc_CU_process_ue_modification_required(MessageDef *msg_p, instance_
     /* trigger reconfiguration */
     if (!UE->ongoing_reconfiguration)
       nr_rrc_reconfiguration_req(rrc, UE, 0, 0);
+    else
+      LOG_E(NR_RRC, "UE %d: reconfiguration ongoing, cannot trigger new reconfiguration\n", UE->rrc_ue_id);
     return;
   }
   LOG_W(RRC,

openair2/RRC/NR/rrc_gNB_mobility.c

@@ -335,7 +335,26 @@ static void nr_rrc_f1_ho_complete(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE)
 
 static void nr_rrc_cancel_f1_ho(gNB_RRC_INST *rrc, gNB_RRC_UE_t *UE)
 {
-  DevAssert(UE->ho_context != NULL);
+  DevAssert(UE->ho_context != NULL && UE->ho_context->source != NULL);
+
+  // find the transaction of handover (the corresponding reconfig) and abort it
+  for (int i = 0; i < NR_RRC_TRANSACTION_IDENTIFIER_NUMBER; ++i) {
+    if (UE->xids[i] == RRC_DEDICATED_RECONF)
+      UE->xids[i] = RRC_ACTION_NONE;
+  }
+
+  /* we need the original CellGroupConfig */
+  nr_ho_source_cu_t *source_ctx = UE->ho_context->source;
+  ASN_STRUCT_FREE(asn_DEF_NR_CellGroupConfig, UE->masterCellGroup);
+  UE->masterCellGroup = source_ctx->old_cellGroupConfig;
+  source_ctx->old_cellGroupConfig = NULL;
+
+  /* update to old DU assoc id -- RNTI + secondary DU UE ID further below */
+  f1_ue_data_t ue_data = cu_get_f1_ue_data(UE->rrc_ue_id);
+  ue_data.du_assoc_id = source_ctx->du->assoc_id;
+  bool success = cu_update_f1_ue_data(UE->rrc_ue_id, &ue_data);
+  DevAssert(success);
+
   nr_ho_target_cu_t *target_ctx = UE->ho_context->target;
   DevAssert(target_ctx != NULL);
   f1ap_ue_context_rel_cmd_t cmd = {