diff --git a/lib/include/srsran/common/enb_events.h b/lib/include/srsran/common/enb_events.h index 90a29dcb3..e94aaab74 100644 --- a/lib/include/srsran/common/enb_events.h +++ b/lib/include/srsran/common/enb_events.h @@ -49,11 +49,30 @@ public: /// Logs into the underlying log channel when a sector has been stopped. virtual void log_sector_stop(uint32_t cc_idx, uint32_t pci, uint32_t cell_id) = 0; - /// Logs into the underlying log channel a measurement report event.. - virtual void log_measurement_report(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) = 0; - - /// Logs into the underlying log channel a RLF event. - virtual void log_rlf(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) = 0; + /// Logs into the underlying log channel a measurement report event. + virtual void log_measurement_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) = 0; + + /// Logs into the underlying log channel a RLF report. + virtual void log_rlf_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) = 0; + + /// Logs into the underlying log channel a RLF detection event. + virtual void log_rlf_detected(uint32_t enb_cc_idx, const std::string& type, uint16_t rnti) = 0; + + /// Logs into the underlying log channel a handover command event. + virtual void log_handover_command(uint32_t enb_cc_idx, + uint32_t target_pci, + uint32_t target_earfcn, + uint16_t new_ue_rnti, + uint16_t rnti) = 0; + + /// Logs into the underlying log channel a connection resume event. + virtual void log_connection_resume(uint32_t enb_cc_idx, uint16_t resume_rnti, uint16_t rnti) = 0; }; /// Singleton class to provide global access to the event_logger_interface interface. diff --git a/lib/src/common/enb_events.cc b/lib/src/common/enb_events.cc index fa985eb41..51a165d8a 100644 --- a/lib/src/common/enb_events.cc +++ b/lib/src/common/enb_events.cc @@ -33,8 +33,24 @@ public: void log_s1_ctx_delete(uint32_t enb_cc_idx, uint32_t mme_id, uint32_t enb_id, uint16_t rnti) override {} void log_sector_start(uint32_t cc_idx, uint32_t pci, uint32_t cell_id) override {} void log_sector_stop(uint32_t cc_idx, uint32_t pci, uint32_t cell_id) override {} - void log_measurement_report(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) override {} - void log_rlf(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) override {} + void log_measurement_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) override + {} + void log_rlf_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) override + {} + void log_rlf_detected(uint32_t enb_cc_idx, const std::string& type, uint16_t rnti) override {} + void log_handover_command(uint32_t enb_cc_idx, + uint32_t target_pci, + uint32_t target_earfcn, + uint16_t new_ue_rnti, + uint16_t rnti) override + {} + void log_connection_resume(uint32_t enb_cc_idx, uint16_t resume_rnti, uint16_t rnti) override {} }; } // namespace @@ -52,6 +68,7 @@ namespace { DECLARE_METRIC("type", metric_type_tag, std::string, ""); DECLARE_METRIC("timestamp", metric_timestamp_tag, double, ""); DECLARE_METRIC("sector_id", metric_sector_id, uint32_t, ""); +DECLARE_METRIC("cell_id", metric_cell_id, uint32_t, ""); DECLARE_METRIC("event_name", metric_event_name, std::string, ""); DECLARE_METRIC("rnti", metric_rnti, uint16_t, ""); @@ -90,10 +107,13 @@ DECLARE_METRIC_SET("event_data", mset_s1apctx_event, metric_ue_mme_id, metric_ue using s1apctx_event_t = srslog:: build_context_type; -/// Context for the RLF event. -DECLARE_METRIC_SET("event_data", mset_rlfctx_event, metric_asn1_length, metric_asn1_message, metric_rnti); -using rlfctx_event_t = srslog:: - build_context_type; +/// Context for the RLF report event. +DECLARE_METRIC_SET("event_data", mset_rlf_report_event, metric_asn1_length, metric_asn1_message, metric_rnti); +using rlf_report_event_t = srslog::build_context_type; /// Context for measurement report. DECLARE_METRIC_SET("event_data", mset_meas_report_event, metric_asn1_length, metric_asn1_message, metric_rnti); @@ -103,6 +123,37 @@ using meas_report_event_t = srslog::build_context_type; +/// Context for the handover command event. +DECLARE_METRIC("target_pci", metric_target_pci, uint32_t, ""); +DECLARE_METRIC("target_earfcn", metric_target_earfcn, uint32_t, ""); +DECLARE_METRIC("new_ue_rnti", metric_new_ue_rnti, uint32_t, ""); +DECLARE_METRIC_SET("event_data", + mset_ho_cmd_event, + metric_rnti, + metric_target_pci, + metric_target_earfcn, + metric_new_ue_rnti); +using ho_cmd_t = srslog:: + build_context_type; + +/// Context for the connection resume event. +DECLARE_METRIC("resume_rnti", metric_resume_rnti, uint32_t, ""); +DECLARE_METRIC_SET("event_data", mset_conn_resume_event, metric_rnti, metric_resume_rnti); +using conn_resume_t = srslog::build_context_type; + +/// Context for the RLF detected event. +DECLARE_METRIC("type", metric_rlf_type, std::string, ""); +DECLARE_METRIC_SET("event_data", mset_rlf_detected_event, metric_rnti, metric_rlf_type); +using rlf_detected_t = srslog::build_context_type; + /// Logs events into the configured log channel. class logging_event_logger : public event_logger_interface { @@ -187,7 +238,10 @@ public: event_channel(ctx); } - void log_measurement_report(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) override + void log_measurement_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) override { meas_report_event_t ctx(""); @@ -195,23 +249,71 @@ public: ctx.write(get_time_stamp()); ctx.write(enb_cc_idx); ctx.write("measurement_report"); - ctx.get().write(asn1.size()); - ctx.get().write(asn1); + ctx.get().write(asn1_oct_str.size()); + ctx.get().write(asn1_oct_str); ctx.get().write(rnti); event_channel(ctx); } - void log_rlf(uint32_t enb_cc_idx, const std::string& asn1, uint16_t rnti) override + void log_rlf_report(uint32_t enb_cc_idx, + const std::string& asn1_oct_str, + const std::string& asn1_txt_str, + uint16_t rnti) override + { + rlf_report_event_t ctx(""); + + ctx.write("event"); + ctx.write(get_time_stamp()); + ctx.write(enb_cc_idx); + ctx.write("rlf_report"); + ctx.get().write(asn1_oct_str.size()); + ctx.get().write(asn1_oct_str); + ctx.get().write(rnti); + event_channel(ctx); + } + + void log_rlf_detected(uint32_t enb_cc_idx, const std::string& type, uint16_t rnti) override + { + rlf_detected_t ctx(""); + + ctx.write("event"); + ctx.write(get_time_stamp()); + ctx.write(enb_cc_idx); + ctx.write("rlf_detected"); + ctx.get().write(rnti); + ctx.get().write(type); + event_channel(ctx); + } + + void log_handover_command(uint32_t enb_cc_idx, + uint32_t target_pci, + uint32_t target_earfcn, + uint16_t new_ue_rnti, + uint16_t rnti) override + { + ho_cmd_t ctx(""); + + ctx.write("event"); + ctx.write(get_time_stamp()); + ctx.write(enb_cc_idx); + ctx.write("ho_command"); + ctx.get().write(rnti); + ctx.get().write(target_pci); + ctx.get().write(target_earfcn); + ctx.get().write(new_ue_rnti); + event_channel(ctx); + } + + void log_connection_resume(uint32_t enb_cc_idx, uint16_t resume_rnti, uint16_t rnti) override { - rlfctx_event_t ctx(""); + conn_resume_t ctx(""); ctx.write("event"); ctx.write(get_time_stamp()); ctx.write(enb_cc_idx); - ctx.write("radio_link_failure"); - ctx.get().write(asn1.size()); - ctx.get().write(asn1); - ctx.get().write(rnti); + ctx.write("connection_resume"); + ctx.get().write(rnti); + ctx.get().write(resume_rnti); event_channel(ctx); } diff --git a/srsenb/hdr/stack/rrc/rrc_ue.h b/srsenb/hdr/stack/rrc/rrc_ue.h index 3f66332cb..40f18937b 100644 --- a/srsenb/hdr/stack/rrc/rrc_ue.h +++ b/srsenb/hdr/stack/rrc/rrc_ue.h @@ -151,6 +151,8 @@ public: void save_ul_message(srsran::unique_byte_buffer_t pdu) { last_ul_msg = std::move(pdu); } + const ue_cell_ded_list& get_cell_list() const { return ue_cell_list; } + uint16_t rnti = 0; rrc* parent = nullptr; diff --git a/srsenb/src/stack/rrc/rrc.cc b/srsenb/src/stack/rrc/rrc.cc index d5967eba4..3368e9385 100644 --- a/srsenb/src/stack/rrc/rrc.cc +++ b/srsenb/src/stack/rrc/rrc.cc @@ -20,6 +20,7 @@ #include "srsran/asn1/asn1_utils.h" #include "srsran/asn1/rrc_utils.h" #include "srsran/common/bcd_helpers.h" +#include "srsran/common/enb_events.h" #include "srsran/common/standard_streams.h" #include "srsran/common/string_helpers.h" #include "srsran/interfaces/enb_mac_interfaces.h" @@ -276,6 +277,10 @@ void rrc::upd_user(uint16_t new_rnti, uint16_t old_rnti) old_it->second->send_connection_reconf(); } } + + // Log event. + event_logger::get().log_connection_resume( + ue_ptr->get_cell_list().get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, new_rnti, old_rnti); } // Note: this method is not part of UE methods, because the UE context may not exist anymore when reject is sent diff --git a/srsenb/src/stack/rrc/rrc_mobility.cc b/srsenb/src/stack/rrc/rrc_mobility.cc index f62863a1e..8b0316b94 100644 --- a/srsenb/src/stack/rrc/rrc_mobility.cc +++ b/srsenb/src/stack/rrc/rrc_mobility.cc @@ -269,9 +269,12 @@ void rrc::ue::rrc_mobility::handle_ue_meas_report(const meas_report_s& msg, srsr } } + asn1::json_writer json_writer; + msg.to_json(json_writer); event_logger::get().log_measurement_report( rrc_ue->ue_cell_list.get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, asn1::octstring_to_string(pdu->msg, pdu->N_bytes), + json_writer.to_string(), rrc_ue->rnti); } @@ -709,6 +712,13 @@ void rrc::ue::rrc_mobility::s1_source_ho_st::handle_ho_cmd(wait_ho_cmd& s, const static_cast(procedure_result_code::none), rrc_ue->rnti); + event_logger::get().log_handover_command( + rrc_ue->ue_cell_list.get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, + reconf.crit_exts.c1().rrc_conn_recfg_r8().mob_ctrl_info.target_pci, + reconf.crit_exts.c1().rrc_conn_recfg_r8().mob_ctrl_info.carrier_freq.dl_carrier_freq, + reconf.crit_exts.c1().rrc_conn_recfg_r8().mob_ctrl_info.new_ue_id.to_number(), + rrc_ue->rnti); + /* Start S1AP eNBStatusTransfer Procedure */ asn1::s1ap::cause_c cause = start_enb_status_transfer(*ho_cmd.s1ap_ho_cmd); if (cause.type().value != asn1::s1ap::cause_c::types_opts::nulltype) { diff --git a/srsenb/src/stack/rrc/rrc_ue.cc b/srsenb/src/stack/rrc/rrc_ue.cc index 29af60882..70dbb4d4f 100644 --- a/srsenb/src/stack/rrc/rrc_ue.cc +++ b/srsenb/src/stack/rrc/rrc_ue.cc @@ -228,11 +228,16 @@ void rrc::ue::activity_timer_expired(const activity_timeout_type_t type) void rrc::ue::rlf_timer_expired(uint32_t timeout_id) { activity_timer.stop(); + + std::string event_type = "Unknown"; if (timeout_id == phy_dl_rlf_timer.id()) { + event_type = "dl_rlf"; parent->logger.info("DL RLF timer for rnti=0x%x expired after %d ms", rnti, phy_dl_rlf_timer.time_elapsed()); } else if (timeout_id == phy_ul_rlf_timer.id()) { + event_type = "ul_rlf"; parent->logger.info("UL RLF timer for rnti=0x%x expired after %d ms", rnti, phy_ul_rlf_timer.time_elapsed()); } else if (timeout_id == rlc_rlf_timer.id()) { + event_type = "rlc_rlf"; parent->logger.info("RLC RLF timer for rnti=0x%x expired after %d ms", rnti, rlc_rlf_timer.time_elapsed()); } @@ -243,6 +248,10 @@ void rrc::ue::rlf_timer_expired(uint32_t timeout_id) parent->s1ap->user_release(rnti, asn1::s1ap::cause_radio_network_opts::radio_conn_with_ue_lost); con_release_result = procedure_result_code::radio_conn_with_ue_lost; + + // Log event. + event_logger::get().log_rlf_detected( + ue_cell_list.get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, event_type, rnti); } void rrc::ue::max_rlc_retx_reached() @@ -907,8 +916,12 @@ void rrc::ue::handle_ue_info_resp(const asn1::rrc::ue_info_resp_r9_s& msg, srsra { auto& resp_r9 = msg.crit_exts.c1().ue_info_resp_r9(); if (resp_r9.rlf_report_r9_present) { - std::string msg_str = asn1::octstring_to_string(pdu->msg, pdu->N_bytes); - event_logger::get().log_rlf(ue_cell_list.get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, msg_str, rnti); + asn1::json_writer json_writer; + msg.to_json(json_writer); + event_logger::get().log_rlf_report(ue_cell_list.get_ue_cc_idx(UE_PCELL_CC_IDX)->cell_common->enb_cc_idx, + asn1::octstring_to_string(pdu->msg, pdu->N_bytes), + json_writer.to_string(), + rnti); } if (resp_r9.rach_report_r9_present) { // TODO: Handle RACH-Report