fix S1AP UE Capability Indication message. Created helper to log received S1AP messages

lib/include/srslte/adt/span.h

@@ -232,6 +232,9 @@ inline bool operator!=(span<T> lhs, span<T> rhs)
   return not lhs.equals(rhs);
 }
 
+template <typename T>
+using const_span = span<const T>;
+
 } // namespace srslte
 
 #endif // SRSLTE_SPAN_H

lib/src/asn1/asn1_utils.cc

@@ -788,8 +788,8 @@ SRSASN_CODE unpack_length(uint32_t& val, cbit_ref& bref, bool aligned)
       val = (val << 8u) + val_octet_2;
       return SRSASN_SUCCESS;
     }
-    // TODO: Error message
+    log_error("Not handling octet strings longer than 16383 octets");
-    return SRSASN_ERROR_ENCODE_FAIL;
+    return SRSASN_ERROR_DECODE_FAIL;
   }
 }
 

srsenb/hdr/stack/rrc/rrc_mobility.h

@@ -108,9 +108,9 @@ private:
     };
     ho_meas_report_ev report;
 
-    struct wait_ho_cmd {
+    void enter(rrc_mobility* f, const ho_meas_report_ev& ev);
-      void enter(s1_source_ho_st* f, const ho_meas_report_ev& ev);
+
-    };
+    struct wait_ho_cmd {};
     struct status_transfer_st {};
 
     explicit s1_source_ho_st(rrc_mobility* parent_);

srsenb/hdr/stack/upper/s1ap.h

@@ -273,6 +273,7 @@ private:
 
   ue*         find_s1apmsg_user(uint32_t enb_id, uint32_t mme_id);
   std::string get_cause(const asn1::s1ap::cause_c& c);
+  void        log_s1ap_msg(const asn1::s1ap::s1ap_pdu_c& msg, srslte::const_span<uint8_t> sdu, bool is_rx);
 
   srslte::proc_t<s1_setup_proc_t> s1setup_proc;
 };

srsenb/src/stack/rrc/rrc_mobility.cc

@@ -369,7 +369,6 @@ bool rrc::ue::rrc_mobility::start_ho_preparation(uint32_t target_eci,
   buffer->N_bytes = bref.distance_bytes();
 
   bool success = rrc_enb->s1ap->send_ho_required(rrc_ue->rnti, target_eci, target_plmn, std::move(buffer));
-  Info("sent s1ap msg with HO Required");
   return success;
 }
 
@@ -571,15 +570,14 @@ bool rrc::ue::rrc_mobility::s1_source_ho_st::start_enb_status_transfer(const asn
   return true;
 }
 
-void rrc::ue::rrc_mobility::s1_source_ho_st::wait_ho_cmd::enter(s1_source_ho_st* f, const ho_meas_report_ev& ev)
+void rrc::ue::rrc_mobility::s1_source_ho_st::enter(rrc_mobility* f, const ho_meas_report_ev& ev)
 {
-  srslte::console("Starting S1 Handover of rnti=0x%x to cellid=0x%x.\n", f->rrc_ue->rnti, ev.target_eci);
+  srslte::console("Starting S1 Handover of rnti=0x%x to cellid=0x%x.\n", rrc_ue->rnti, ev.target_eci);
-  f->get_logger().info("Starting S1 Handover of rnti=0x%x to cellid=0x%x.", f->rrc_ue->rnti, ev.target_eci);
+  logger.info("Starting S1 Handover of rnti=0x%x to cellid=0x%x.", rrc_ue->rnti, ev.target_eci);
-  f->report = ev;
+  report = ev;
 
-  bool success = f->parent_fsm()->start_ho_preparation(f->report.target_eci, f->report.meas_obj->meas_obj_id, false);
+  if (not parent_fsm()->start_ho_preparation(report.target_eci, report.meas_obj->meas_obj_id, false)) {
-  if (not success) {
+    trigger(srslte::failure_ev{});
-    f->trigger(srslte::failure_ev{});
   }
 }
 

srsenb/src/stack/rrc/rrc_ue.cc

@@ -676,28 +676,37 @@ bool rrc::ue::handle_ue_cap_info(ue_cap_info_s* msg)
     if (msg_r8->ue_cap_rat_container_list[i].rat_type != rat_type_e::eutra) {
       parent->logger.warning("Not handling UE capability information for RAT type %s",
                              msg_r8->ue_cap_rat_container_list[i].rat_type.to_string().c_str());
-    } else {
+      continue;
-      asn1::cbit_ref bref(msg_r8->ue_cap_rat_container_list[i].ue_cap_rat_container.data(),
+    }
-                          msg_r8->ue_cap_rat_container_list[i].ue_cap_rat_container.size());
+    asn1::cbit_ref bref(msg_r8->ue_cap_rat_container_list[i].ue_cap_rat_container.data(),
-      if (eutra_capabilities.unpack(bref) != asn1::SRSASN_SUCCESS) {
+                        msg_r8->ue_cap_rat_container_list[i].ue_cap_rat_container.size());
-        parent->logger.error("Failed to unpack EUTRA capabilities message");
+    if (eutra_capabilities.unpack(bref) != asn1::SRSASN_SUCCESS) {
-        return false;
+      parent->logger.error("Failed to unpack EUTRA capabilities message");
-      }
+      return false;
-      if (parent->logger.debug.enabled()) {
+    }
-        asn1::json_writer js{};
+    if (parent->logger.debug.enabled()) {
-        eutra_capabilities.to_json(js);
+      asn1::json_writer js{};
-        parent->logger.debug("rnti=0x%x EUTRA capabilities: %s", rnti, js.to_string().c_str());
+      eutra_capabilities.to_json(js);
-      }
+      parent->logger.debug("rnti=0x%x EUTRA capabilities: %s", rnti, js.to_string().c_str());
-      eutra_capabilities_unpacked = true;
-      ue_capabilities             = srslte::make_rrc_ue_capabilities(eutra_capabilities);
-
-      parent->logger.info("UE rnti: 0x%x category: %d", rnti, eutra_capabilities.ue_category);
-
-      srslte::unique_byte_buffer_t pdu = srslte::allocate_unique_buffer(*pool);
-      pdu->N_bytes                     = msg_r8->ue_cap_rat_container_list[0].ue_cap_rat_container.size();
-      memcpy(pdu->msg, msg_r8->ue_cap_rat_container_list[0].ue_cap_rat_container.data(), pdu->N_bytes);
-      parent->s1ap->send_ue_cap_info_indication(rnti, std::move(pdu));
     }
+    eutra_capabilities_unpacked = true;
+    ue_capabilities             = srslte::make_rrc_ue_capabilities(eutra_capabilities);
+
+    parent->logger.info("UE rnti: 0x%x category: %d", rnti, eutra_capabilities.ue_category);
+  }
+
+  if (eutra_capabilities_unpacked) {
+    srslte::unique_byte_buffer_t pdu = srslte::allocate_unique_buffer(*pool);
+    asn1::bit_ref                bref2{pdu->msg, pdu->get_tailroom()};
+    msg->pack(bref2);
+    asn1::rrc::ue_radio_access_cap_info_s ue_rat_caps;
+    auto& dest = ue_rat_caps.crit_exts.set_c1().set_ue_radio_access_cap_info_r8().ue_radio_access_cap_info;
+    dest.resize(bref2.distance_bytes());
+    memcpy(dest.data(), pdu->msg, bref2.distance_bytes());
+    bref2 = asn1::bit_ref{pdu->msg, pdu->get_tailroom()};
+    ue_rat_caps.pack(bref2);
+    pdu->N_bytes = bref2.distance_bytes();
+    parent->s1ap->send_ue_cap_info_indication(rnti, std::move(pdu));
   }
 
   return true;

srsenb/src/stack/upper/s1ap.cc

@@ -511,7 +511,6 @@ bool s1ap::handle_mme_rx_msg(srslte::unique_byte_buffer_t pdu,
     return false;
   }
 
-  logger.info(pdu->msg, pdu->N_bytes, "Received S1AP PDU");
   handle_s1ap_rx_pdu(pdu.get());
   return true;
 }
@@ -527,12 +526,13 @@ bool s1ap::handle_s1ap_rx_pdu(srslte::byte_buffer_t* pdu)
   asn1::cbit_ref bref(pdu->msg, pdu->N_bytes);
 
   if (rx_pdu.unpack(bref) != asn1::SRSASN_SUCCESS) {
-    logger.error("Failed to unpack received PDU");
+    logger.error(pdu->msg, pdu->N_bytes, "Failed to unpack received PDU");
     cause_c cause;
     cause.set_protocol().value = cause_protocol_opts::transfer_syntax_error;
     send_error_indication(SRSLTE_INVALID_RNTI, cause);
     return false;
   }
+  log_s1ap_msg(rx_pdu, srslte::make_span(*pdu), true);
 
   switch (rx_pdu.type().value) {
     case s1ap_pdu_c::types_opts::init_msg:
@@ -586,7 +586,6 @@ bool s1ap::handle_successfuloutcome(const successful_outcome_s& msg)
     case s1ap_elem_procs_o::successful_outcome_c::types_opts::ho_cmd:
       return handle_s1hocommand(msg.value.ho_cmd());
     case s1ap_elem_procs_o::successful_outcome_c::types_opts::ho_cancel_ack:
-      logger.info("Received %s", msg.value.type().to_string().c_str());
       return true;
     default:
       logger.error("Unhandled successful outcome message: %s", msg.value.type().to_string().c_str());
@@ -609,7 +608,6 @@ bool s1ap::handle_unsuccessfuloutcome(const unsuccessful_outcome_s& msg)
 
 bool s1ap::handle_s1setupresponse(const asn1::s1ap::s1_setup_resp_s& msg)
 {
-  logger.info("Received S1SetupResponse");
   s1setupresponse = msg;
   mme_connected   = true;
   s1_setup_proc_t::s1setupresult res;
@@ -620,7 +618,6 @@ bool s1ap::handle_s1setupresponse(const asn1::s1ap::s1_setup_resp_s& msg)
 
 bool s1ap::handle_dlnastransport(const dl_nas_transport_s& msg)
 {
-  logger.info("Received DownlinkNASTransport");
   if (msg.ext) {
     logger.warning("Not handling S1AP message extension");
   }
@@ -649,7 +646,6 @@ bool s1ap::handle_dlnastransport(const dl_nas_transport_s& msg)
 
 bool s1ap::handle_initialctxtsetuprequest(const init_context_setup_request_s& msg)
 {
-  logger.info("Received InitialContextSetupRequest");
   if (msg.ext) {
     logger.warning("Not handling S1AP message extension");
   }
@@ -691,7 +687,6 @@ bool s1ap::handle_paging(const asn1::s1ap::paging_s& msg)
 
 bool s1ap::handle_erabsetuprequest(const erab_setup_request_s& msg)
 {
-  logger.info("Received ERABSetupRequest");
   if (msg.ext) {
     logger.warning("Not handling S1AP message extension");
   }
@@ -706,7 +701,6 @@ bool s1ap::handle_erabsetuprequest(const erab_setup_request_s& msg)
 
 bool s1ap::handle_erabmodifyrequest(const erab_modify_request_s& msg)
 {
-  logger.info("Received ERABModifyRequest");
   std::vector<uint16_t> erab_successful_modified = {};
   std::vector<uint16_t> erab_failed_to_modify    = {};
 
@@ -739,7 +733,6 @@ bool s1ap::handle_erabmodifyrequest(const erab_modify_request_s& msg)
  */
 bool s1ap::handle_erabreleasecommand(const erab_release_cmd_s& msg)
 {
-  logger.info("Received ERABReleaseCommand");
   std::vector<uint16_t> erab_successful_release = {};
   std::vector<uint16_t> erab_failed_to_release  = {};
 
@@ -765,7 +758,6 @@ bool s1ap::handle_erabreleasecommand(const erab_release_cmd_s& msg)
 
 bool s1ap::handle_uecontextmodifyrequest(const ue_context_mod_request_s& msg)
 {
-  logger.info("Received UeContextModificationRequest");
   ue* u = find_s1apmsg_user(msg.protocol_ies.enb_ue_s1ap_id.value.value, msg.protocol_ies.mme_ue_s1ap_id.value.value);
   if (u == nullptr) {
     return false;
@@ -798,7 +790,6 @@ bool s1ap::handle_uecontextmodifyrequest(const ue_context_mod_request_s& msg)
 
 bool s1ap::handle_uectxtreleasecommand(const ue_context_release_cmd_s& msg)
 {
-  logger.info("Received UEContextReleaseCommand");
   if (msg.ext) {
     logger.warning("Not handling S1AP message extension");
   }
@@ -845,7 +836,6 @@ bool s1ap::handle_s1setupfailure(const asn1::s1ap::s1_setup_fail_s& msg)
 
 bool s1ap::handle_hopreparationfailure(const ho_prep_fail_s& msg)
 {
-  logger.info("Received HO Preparation Failure");
   ue* u = find_s1apmsg_user(msg.protocol_ies.enb_ue_s1ap_id.value.value, msg.protocol_ies.mme_ue_s1ap_id.value.value);
   if (u == nullptr) {
     return false;
@@ -856,7 +846,6 @@ bool s1ap::handle_hopreparationfailure(const ho_prep_fail_s& msg)
 
 bool s1ap::handle_s1hocommand(const asn1::s1ap::ho_cmd_s& msg)
 {
-  logger.info("Received S1 HO Command");
   ue* u = find_s1apmsg_user(msg.protocol_ies.enb_ue_s1ap_id.value.value, msg.protocol_ies.mme_ue_s1ap_id.value.value);
   if (u == nullptr) {
     return false;
@@ -873,9 +862,6 @@ bool s1ap::handle_ho_request(const asn1::s1ap::ho_request_s& msg)
 {
   uint16_t rnti = SRSLTE_INVALID_RNTI;
 
-  logger.info("Received S1 HO Request");
-  srslte::console("Received S1 HO Request\n");
-
   auto on_scope_exit = srslte::make_scope_exit([this, &rnti, msg]() {
     // If rnti is not allocated successfully, remove from s1ap and send handover failure
     if (rnti == SRSLTE_INVALID_RNTI) {
@@ -990,9 +976,6 @@ bool s1ap::send_ho_req_ack(const asn1::s1ap::ho_request_s&                msg,
 
 bool s1ap::handle_mme_status_transfer(const asn1::s1ap::mme_status_transfer_s& msg)
 {
-  logger.info("Received S1 MMEStatusTransfer");
-  srslte::console("Received S1 MMEStatusTransfer\n");
-
   ue* u = find_s1apmsg_user(msg.protocol_ies.enb_ue_s1ap_id.value.value, msg.protocol_ies.mme_ue_s1ap_id.value.value);
   if (u == nullptr) {
     return false;
@@ -1452,8 +1435,8 @@ bool s1ap::ue::send_ue_cap_info_indication(srslte::unique_byte_buffer_t ue_radio
   container.enb_ue_s1ap_id.value = ctxt.enb_ue_s1ap_id;
   container.mme_ue_s1ap_id.value = ctxt.mme_ue_s1ap_id;
 
-  asn1::cbit_ref bref{ue_radio_cap->msg, ue_radio_cap->N_bytes};
+  container.ue_radio_cap.value.resize(ue_radio_cap->N_bytes);
-  container.ue_radio_cap.value.unpack(bref);
+  memcpy(container.ue_radio_cap.value.data(), ue_radio_cap->msg, ue_radio_cap->N_bytes);
 
   return s1ap_ptr->sctp_send_s1ap_pdu(tx_pdu, ctxt.rnti, "UECapabilityInfoIndication");
 }
@@ -1804,4 +1787,26 @@ bool s1ap::ue::send_enb_status_transfer_proc(std::vector<bearer_status_info>& be
   return s1ap_ptr->sctp_send_s1ap_pdu(tx_pdu, ctxt.rnti, "ENBStatusTransfer");
 }
 
+void s1ap::log_s1ap_msg(const asn1::s1ap::s1ap_pdu_c& msg, srslte::const_span<uint8_t> sdu, bool is_rx)
+{
+  std::string msg_type;
+
+  switch (msg.type().value) {
+    case s1ap_pdu_c::types_opts::init_msg:
+      msg_type = msg.init_msg().value.type().to_string();
+      break;
+    case s1ap_pdu_c::types_opts::successful_outcome:
+      msg_type = msg.successful_outcome().value.type().to_string();
+      break;
+    case s1ap_pdu_c::types_opts::unsuccessful_outcome:
+      msg_type = msg.unsuccessful_outcome().value.type().to_string();
+      break;
+    default:
+      logger.warning("Unrecognized S1AP message type\n");
+      return;
+  }
+
+  logger.info(sdu.data(), sdu.size(), "%s S1AP SDU - %s", is_rx ? "Rx" : "Tx", msg_type.c_str());
+}
+
 } // namespace srsenb