nr,gnb,rrc: add test logger delimiter; handle rrc setup complete

lib/include/srsran/common/test_common.h

@@ -137,6 +137,7 @@ inline void test_init(int argc, char** argv)
   srsran_debug_handle_crash(argc, argv);
 
   srslog::fetch_basic_logger("ALL").set_level(srslog::basic_levels::info);
+  srslog::fetch_basic_logger("TEST").set_level(srslog::basic_levels::info);
 
   // Start the log backend.
   srslog::init();
@@ -153,6 +154,33 @@ inline void copy_msg_to_buffer(unique_byte_buffer_t& pdu, const_byte_span msg)
   pdu->N_bytes = msg.size();
 }
 
+class test_delimit_logger
+{
+  const size_t delimiter_length = 128;
+
+public:
+  template <typename... Args>
+  explicit test_delimit_logger(const char* test_name_fmt, Args&&... args)
+  {
+    test_name               = fmt::format(test_name_fmt, std::forward<Args>(args)...);
+    std::string name_str    = fmt::format("[ Test \"{}\" ]", test_name);
+    double      nof_repeats = (delimiter_length - name_str.size()) / 2.0;
+    fmt::print("{0:=>{1}}{2}{0:=>{3}}\n", "", (int)floor(nof_repeats), name_str, (int)ceil(nof_repeats));
+  }
+  test_delimit_logger(const test_delimit_logger&) = delete;
+  test_delimit_logger(test_delimit_logger&&)      = delete;
+  test_delimit_logger& operator=(const test_delimit_logger&) = delete;
+  test_delimit_logger& operator=(test_delimit_logger&&) = delete;
+  ~test_delimit_logger()
+  {
+    srslog::flush();
+    fmt::print("{:=>{}}\n", "", delimiter_length);
+  }
+
+private:
+  std::string test_name;
+};
+
 } // namespace srsran
 
 #define CONDERROR(cond, fmt, ...) srsran_assert(not(cond), fmt, ##__VA_ARGS__)

srsenb/src/stack/rrc/rrc.cc

@@ -634,7 +634,7 @@ void rrc::sgnb_release_ack(uint16_t eutra_rnti)
 
 void rrc::parse_ul_ccch(ue& ue, srsran::unique_byte_buffer_t pdu)
 {
-  srsran_assert(pdu != nullptr, "parse_ul_ccch called for empty message");
+  srsran_assert(pdu != nullptr, "handle_ul_ccch called for empty message");
 
   ul_ccch_msg_s  ul_ccch_msg;
   asn1::cbit_ref bref(pdu->msg, pdu->N_bytes);
@@ -667,7 +667,7 @@ void rrc::parse_ul_ccch(ue& ue, srsran::unique_byte_buffer_t pdu)
 ///< User mutex must be hold by caller
 void rrc::parse_ul_dcch(ue& ue, uint32_t lcid, srsran::unique_byte_buffer_t pdu)
 {
-  srsran_assert(pdu != nullptr, "parse_ul_dcch called for empty message");
+  srsran_assert(pdu != nullptr, "handle_ul_dcch called for empty message");
 
   ue.parse_ul_dcch(lcid, std::move(pdu));
 }

srsgnb/hdr/stack/rrc/rrc_nr.h

@@ -123,15 +123,9 @@ public:
 
     void send_dl_ccch(const asn1::rrc_nr::dl_ccch_msg_s& dl_dcch_msg);
 
-    /* TS 38.331 - 5.3.3 RRC connection establishment */
-    void send_rrc_setup();
-    void send_rrc_reject(uint8_t reject_wait_time_secs);
-
     int  handle_sgnb_addition_request(uint16_t eutra_rnti, const sgnb_addition_req_params_t& params);
     void crnti_ce_received();
 
-    void handle_rrc_setup_request(const asn1::rrc_nr::rrc_setup_request_s& msg);
-
     // getters
     bool     is_connected() { return state == rrc_nr_state_t::RRC_CONNECTED; }
     bool     is_idle() { return state == rrc_nr_state_t::RRC_IDLE; }
@@ -151,10 +145,18 @@ public:
     void        set_activity(bool enabled = true);
     void        activity_timer_expired(const activity_timeout_type_t type);
 
+    /* TS 38.331 - 5.3.3 RRC connection establishment */
+    void handle_rrc_setup_request(const asn1::rrc_nr::rrc_setup_request_s& msg);
+    void handle_rrc_setup_complete(const asn1::rrc_nr::rrc_setup_complete_s& msg);
+
   private:
     rrc_nr*  parent = nullptr;
     uint16_t rnti   = SRSRAN_INVALID_RNTI;
 
+    /* TS 38.331 - 5.3.3 RRC connection establishment */
+    void send_rrc_setup();
+    void send_rrc_reject(uint8_t reject_wait_time_secs);
+
     int pack_rrc_reconfiguration(asn1::dyn_octstring& packed_rrc_reconfig);
     int pack_secondary_cell_group_cfg(asn1::dyn_octstring& packed_secondary_cell_config);
 
@@ -260,8 +262,12 @@ private:
 
   /// Private Methods
   void handle_pdu(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu);
-  void parse_ul_ccch(uint16_t rnti, srsran::const_byte_span pdu);
+  void handle_ul_ccch(uint16_t rnti, srsran::const_byte_span pdu);
+  void handle_ul_dcch(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu);
+
+  // TS 38.331, 5.3.3 - RRC connection establishment
   void handle_rrc_setup_request(uint16_t rnti, const asn1::rrc_nr::rrc_setup_request_s& msg);
+
   /// This gets called by rrc_nr::sgnb_addition_request and WILL NOT TRIGGER the RX MSG3 activity timer
   int add_user(uint16_t rnti, const sched_nr_ue_cfg_t& uecfg, bool start_msg3_timer);
 

srsgnb/src/stack/rrc/cell_asn1_config.cc

@@ -297,7 +297,7 @@ int fill_pdcch_cfg_from_enb_cfg(const rrc_nr_cfg_t& cfg, uint32_t cc, pdcch_cfg_
           (search_space_cfg.type == srsran_search_space_type_common_1) or
           (search_space_cfg.type == srsran_search_space_type_common_2) or
           (search_space_cfg.type == srsran_search_space_type_common_3)) {
-        search_spaces[0].search_space_type.set_common();
+        search_spaces[ss_mod_list_idx].search_space_type.set_common();
 
         search_spaces[ss_mod_list_idx].search_space_type.common().dci_format0_minus0_and_format1_minus0_present = true;
       } else {

srsgnb/src/stack/rrc/rrc_nr.cc

@@ -108,8 +108,6 @@ int rrc_nr::init(const rrc_nr_cfg_t&         cfg_,
   config_phy(); // if PHY is not yet initialized, config will be stored and applied on initialization
   config_mac();
 
-  logger.info("Started");
-
   running = true;
 
   return SRSRAN_SUCCESS;
@@ -416,15 +414,14 @@ void rrc_nr::get_metrics(srsenb::rrc_metrics_t& m)
 
 void rrc_nr::handle_pdu(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu)
 {
-  logger.info(pdu.data(), pdu.size(), "Rx %s PDU", get_rb_name(lcid));
-
   switch (static_cast<srsran::nr_srb>(lcid)) {
     case srsran::nr_srb::srb0:
-      parse_ul_ccch(rnti, pdu);
+      handle_ul_ccch(rnti, pdu);
       break;
     case srsran::nr_srb::srb1:
     case srsran::nr_srb::srb2:
-      //        parse_ul_dcch(p.rnti, p.lcid, std::move(p.pdu));
+    case srsran::nr_srb::srb3:
+      handle_ul_dcch(rnti, lcid, std::move(pdu));
       break;
     default:
       std::string errcause = fmt::format("Invalid LCID=%d", lcid);
@@ -433,7 +430,7 @@ void rrc_nr::handle_pdu(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pd
   }
 }
 
-void rrc_nr::parse_ul_ccch(uint16_t rnti, srsran::const_byte_span pdu)
+void rrc_nr::handle_ul_ccch(uint16_t rnti, srsran::const_byte_span pdu)
 {
   // Parse UL-CCCH
   ul_ccch_msg_s ul_ccch_msg;
@@ -463,6 +460,43 @@ void rrc_nr::parse_ul_ccch(uint16_t rnti, srsran::const_byte_span pdu)
   }
 }
 
+void rrc_nr::handle_ul_dcch(uint16_t rnti, uint32_t lcid, srsran::const_byte_span pdu)
+{
+  // Parse UL-DCCH
+  ul_dcch_msg_s ul_dcch_msg;
+  {
+    asn1::cbit_ref bref(pdu.data(), pdu.size());
+    if (ul_dcch_msg.unpack(bref) != asn1::SRSASN_SUCCESS or
+        ul_dcch_msg.msg.type().value != ul_dcch_msg_type_c::types_opts::c1) {
+      log_rx_pdu_fail(rnti, lcid, pdu, "Failed to unpack UL-DCCH message");
+      return;
+    }
+  }
+
+  // Verify UE exists
+  auto ue_it = users.find(rnti);
+  if (ue_it == users.end()) {
+    log_rx_pdu_fail(rnti, lcid, pdu, "Inexistent rnti");
+  }
+  ue& u = *ue_it->second;
+
+  // Log Rx message
+  fmt::memory_buffer fmtbuf, fmtbuf2;
+  fmt::format_to(fmtbuf, "rnti=0x{:x}, {}", rnti, srsran::get_srb_name(srsran::nr_lcid_to_srb(lcid)));
+  fmt::format_to(fmtbuf2, "UL-DCCH.{}", ul_dcch_msg.msg.c1().type().to_string());
+  log_rrc_message(srsran::to_c_str(fmtbuf), Rx, pdu, ul_dcch_msg, srsran::to_c_str(fmtbuf2));
+
+  // Handle message
+  switch (ul_dcch_msg.msg.c1().type().value) {
+    case ul_dcch_msg_type_c::c1_c_::types_opts::rrc_setup_complete:
+      u.handle_rrc_setup_complete(ul_dcch_msg.msg.c1().rrc_setup_complete());
+      break;
+    default:
+      log_rx_pdu_fail(rnti, srb_to_lcid(lte_srb::srb0), pdu, "Unsupported UL-CCCH message type", false);
+      // TODO Remove user
+  }
+}
+
 void rrc_nr::handle_rrc_setup_request(uint16_t rnti, const asn1::rrc_nr::rrc_setup_request_s& msg)
 {
   auto ue_it = users.find(rnti);
@@ -1509,6 +1543,12 @@ void rrc_nr::ue::send_rrc_setup()
   send_dl_ccch(msg);
 }
 
+/// TS 38.331, RRCSetupComplete
+void rrc_nr::ue::handle_rrc_setup_complete(const asn1::rrc_nr::rrc_setup_complete_s& msg)
+{
+  // TODO: handle RRCSetupComplete
+}
+
 /**
  * @brief Deactivate all Bearers (MAC logical channel) for this specific RNTI
  *

srsgnb/src/stack/rrc/test/rrc_nr_test.cc

@@ -39,10 +39,11 @@ int test_cell_cfg(const srsenb::sched_interface::cell_cfg_t& cellcfg)
  * Test 1 - Test default SIB generation
  * Description: Check whether the SIBs were set correctly
  */
-int test_sib_generation()
+void test_sib_generation()
 {
-  srsran::task_scheduler task_sched;
+  srsran::test_delimit_logger test_logger{"SIB generation"};
 
+  srsran::task_scheduler task_sched;
   phy_nr_dummy           phy_obj;
   mac_nr_dummy           mac_obj;
   rlc_dummy              rlc_obj;
@@ -88,14 +89,13 @@ int test_sib_generation()
   pdcch_cfg_common_s& pdcch = sib1.serving_cell_cfg_common.dl_cfg_common.init_dl_bwp.pdcch_cfg_common.setup();
   TESTASSERT(not pdcch.ctrl_res_set_zero_present); // CORESET#0 id is passed in MIB
   TESTASSERT(not pdcch.search_space_zero_present); // SS#0 id is passed in MIB
-
-  return SRSRAN_SUCCESS;
 }
 
 int test_rrc_setup()
 {
-  srsran::task_scheduler task_sched;
+  srsran::test_delimit_logger test_logger{"NSA RRC"};
 
+  srsran::task_scheduler task_sched;
   phy_nr_dummy           phy_obj;
   mac_nr_dummy           mac_obj;
   rlc_dummy              rlc_obj;
@@ -129,8 +129,9 @@ int test_rrc_setup()
 
 void test_rrc_sa_connection()
 {
-  srsran::task_scheduler task_sched;
+  srsran::test_delimit_logger test_logger{"SA RRCConnectionEstablishment"};
 
+  srsran::task_scheduler task_sched;
   phy_nr_dummy           phy_obj;
   mac_nr_dummy           mac_obj;
   rlc_nr_rrc_tester      rlc_obj;
@@ -157,7 +158,7 @@ void test_rrc_sa_connection()
   sched_nr_ue_cfg_t uecfg = get_default_ue_cfg(1);
   TESTASSERT_SUCCESS(rrc_obj.add_user(0x4601, uecfg));
 
-  TESTASSERT_SUCCESS(test_rrc_nr_connection_establishment(task_sched, rrc_obj, rlc_obj, 0x4601));
+  test_rrc_nr_connection_establishment(task_sched, rrc_obj, rlc_obj, 0x4601);
 }
 
 } // namespace srsenb
@@ -177,7 +178,7 @@ int main(int argc, char** argv)
   }
   argparse::parse_args(argc, argv);
 
-  TESTASSERT(srsenb::test_sib_generation() == SRSRAN_SUCCESS);
+  srsenb::test_sib_generation();
   TESTASSERT(srsenb::test_rrc_setup() == SRSRAN_SUCCESS);
   srsenb::test_rrc_sa_connection();
 

srsgnb/src/stack/rrc/test/rrc_nr_test_helpers.cc

@@ -17,7 +17,7 @@ using namespace asn1::rrc_nr;
 
 namespace srsenb {
 
-int test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
+void test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
                                           rrc_nr&                 rrc_obj,
                                           rlc_nr_rrc_tester&      rlc,
                                           uint16_t                rnti)
@@ -49,7 +49,7 @@ int test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
   }
   TESTASSERT_EQ(dl_ccch_msg_type_c::types_opts::c1, dl_ccch_msg.msg.type().value);
   TESTASSERT_EQ(dl_ccch_msg_type_c::c1_c_::types_opts::rrc_setup, dl_ccch_msg.msg.c1().type().value);
-  TESTASSERT_EQ(asn1::rrc_nr::rrc_setup_s::crit_exts_c_::types_opts::rrc_setup,
+  TESTASSERT_EQ(rrc_setup_s::crit_exts_c_::types_opts::rrc_setup,
                 dl_ccch_msg.msg.c1().rrc_setup().crit_exts.type().value);
 
   const rrc_setup_ies_s& setup_ies = dl_ccch_msg.msg.c1().rrc_setup().crit_exts.rrc_setup();
@@ -59,7 +59,17 @@ int test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
   const srb_to_add_mod_s& srb1 = setup_ies.radio_bearer_cfg.srb_to_add_mod_list[0];
   TESTASSERT_EQ(srsran::srb_to_lcid(srsran::nr_srb::srb1), srb1.srb_id);
 
-  return SRSRAN_SUCCESS;
+  ul_dcch_msg_s         ul_dcch_msg;
+  rrc_setup_complete_s& complete         = ul_dcch_msg.msg.set_c1().set_rrc_setup_complete();
+  complete.rrc_transaction_id            = dl_ccch_msg.msg.c1().rrc_setup().rrc_transaction_id;
+  rrc_setup_complete_ies_s& complete_ies = complete.crit_exts.set_rrc_setup_complete();
+  {
+    pdu = srsran::make_byte_buffer();
+    asn1::bit_ref bref{pdu->data(), pdu->get_tailroom()};
+    TESTASSERT_SUCCESS(ul_dcch_msg.pack(bref));
+    pdu->N_bytes = bref.distance_bytes();
+  }
+  rrc_obj.write_pdu(rnti, 1, std::move(pdu));
 }
 
 } // namespace srsenb

srsgnb/src/stack/rrc/test/rrc_nr_test_helpers.h

@@ -49,8 +49,18 @@ public:
   srsran::unique_byte_buffer_t last_sdu;
 };
 
-/// Run TS 38.331, 5.3.3 "RRC connection establishment" to completion
+/**
-int test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
+ * Run TS 38.331, 5.3.3 "RRC connection establishment" to completion
+ * RRC actions:
+ * - Rx RRCSetupRequest
+ * - Tx RRCSetup to lower layers
+ * - Tx RRCSetupComplete
+ * Checks:
+ * - the RRC sends RRCSetup as reply to RRCSetupRequest
+ * - verify that RRCSetup rnti, lcid are correct
+ * - verify that RRCSetup adds an SRB1
+ */
+void test_rrc_nr_connection_establishment(srsran::task_scheduler& task_sched,
                                           rrc_nr&                 rrc_obj,
                                           rlc_nr_rrc_tester&      rlc,
                                           uint16_t                rnti);