From c18e35bc934d033a0b117c5ae86ea4b3865ab89c Mon Sep 17 00:00:00 2001 From: faluco <63966637+faluco@users.noreply.github.com> Date: Fri, 29 Jan 2021 11:29:20 +0100 Subject: [PATCH] Upgrade loggers in srsepc (#2167) * Started logger replacement in epc main. * Replaced loggers in nas and s1ap. * Replace loggers in nas statics. * Replaced loggers in s1ap ctx mngmt. * Replace loggers in s1ap erab mngmt. * Replaced loggers in s1ap mngmt proc. * Replaced loggers in s1ap nas transport. * Replaced loggers in s1ap paging. * Replaced loggers in mme. * Replaced loggers in mme gtpc. * Started removing logger injection in init functions and cleaned up argument passing to nas statics. * Remove logger injection from mme and s1ap. * Replaced loggers in the hss class. * Replaced loggers in gtpc. * Replaced loggers in GTPU and SPGW. * Replaced loggers in MBMS. --- srsepc/hdr/hss/hss.h | 5 +- srsepc/hdr/mbms-gw/mbms-gw.h | 2 + srsepc/hdr/mme/mme.h | 9 +- srsepc/hdr/mme/mme_gtpc.h | 6 +- srsepc/hdr/mme/nas.h | 39 +-- srsepc/hdr/mme/s1ap.h | 8 +- srsepc/hdr/mme/s1ap_ctx_mngmt_proc.h | 4 +- srsepc/hdr/mme/s1ap_erab_mngmt_proc.h | 4 +- srsepc/hdr/mme/s1ap_mngmt_proc.h | 5 +- srsepc/hdr/mme/s1ap_nas_transport.h | 2 +- srsepc/hdr/mme/s1ap_paging.h | 7 +- srsepc/hdr/spgw/gtpc.h | 9 +- srsepc/hdr/spgw/gtpu.h | 3 + srsepc/hdr/spgw/spgw.h | 9 +- srsepc/src/hss/hss.cc | 128 ++++--- srsepc/src/main.cc | 33 +- srsepc/src/mbms-gw/main.cc | 7 +- srsepc/src/mbms-gw/mbms-gw.cc | 46 +-- srsepc/src/mme/mme.cc | 44 +-- srsepc/src/mme/mme_gtpc.cc | 110 +++--- srsepc/src/mme/nas.cc | 460 ++++++++++++------------- srsepc/src/mme/s1ap.cc | 124 ++++--- srsepc/src/mme/s1ap_ctx_mngmt_proc.cc | 65 ++-- srsepc/src/mme/s1ap_erab_mngmt_proc.cc | 13 +- srsepc/src/mme/s1ap_mngmt_proc.cc | 21 +- srsepc/src/mme/s1ap_nas_transport.cc | 96 +++--- srsepc/src/mme/s1ap_paging.cc | 9 +- srsepc/src/spgw/gtpc.cc | 121 +++---- srsepc/src/spgw/gtpu.cc | 85 +++-- srsepc/src/spgw/spgw.cc | 23 +- 30 files changed, 735 insertions(+), 762 deletions(-) diff --git a/srsepc/hdr/hss/hss.h b/srsepc/hdr/hss/hss.h index cf414d2e8..ee06bf4ee 100644 --- a/srsepc/hdr/hss/hss.h +++ b/srsepc/hdr/hss/hss.h @@ -23,6 +23,7 @@ #include "srslte/common/log.h" #include "srslte/common/log_filter.h" #include "srslte/interfaces/epc_interfaces.h" +#include "srslte/srslog/srslog.h" #include #include #include @@ -68,7 +69,7 @@ class hss : public hss_interface_nas public: static hss* get_instance(void); static void cleanup(void); - int init(hss_args_t* hss_args, srslte::log_filter* hss_log); + int init(hss_args_t* hss_args); void stop(void); virtual bool gen_auth_info_answer(uint64_t imsi, uint8_t* k_asme, uint8_t* autn, uint8_t* rand, uint8_t* xres); @@ -111,7 +112,7 @@ private: std::string db_file; /*Logs*/ - srslte::log_filter* m_hss_log; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("HSS"); uint16_t mcc; uint16_t mnc; diff --git a/srsepc/hdr/mbms-gw/mbms-gw.h b/srsepc/hdr/mbms-gw/mbms-gw.h index d6a3a762e..39dc8e812 100644 --- a/srsepc/hdr/mbms-gw/mbms-gw.h +++ b/srsepc/hdr/mbms-gw/mbms-gw.h @@ -24,6 +24,7 @@ #include "srslte/common/log_filter.h" #include "srslte/common/logmap.h" #include "srslte/common/threads.h" +#include "srslte/srslog/srslog.h" #include "srslte/srslte.h" #include @@ -73,6 +74,7 @@ private: bool m_running; srslte::byte_buffer_pool* m_pool; srslte::log_ref m_mbms_gw_log; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("MBMS"); bool m_sgi_mb_up; int m_sgi_mb_if; diff --git a/srsepc/hdr/mme/mme.h b/srsepc/hdr/mme/mme.h index d69d52fbd..8bace603c 100644 --- a/srsepc/hdr/mme/mme.h +++ b/srsepc/hdr/mme/mme.h @@ -46,10 +46,7 @@ public: static mme* get_instance(void); static void cleanup(void); - int init(mme_args_t* args, - srslte::log_filter* nas_log, - srslte::log_filter* s1ap_log, - srslte::log_filter* mme_gtpc_log); + int init(mme_args_t* args); void stop(); int get_s1_mme(); void run_thread(); @@ -77,9 +74,7 @@ private: void handle_timer_expire(int timer_fd); // Logs - srslte::log_filter* m_nas_log; - srslte::log_filter* m_s1ap_log; - srslte::log_filter* m_mme_gtpc_log; + srslog::basic_logger& m_s1ap_logger = srslog::fetch_basic_logger("S1AP"); }; } // namespace srsepc diff --git a/srsepc/hdr/mme/mme_gtpc.h b/srsepc/hdr/mme/mme_gtpc.h index 47e5511f1..4ba058d4d 100644 --- a/srsepc/hdr/mme/mme_gtpc.h +++ b/srsepc/hdr/mme/mme_gtpc.h @@ -37,7 +37,7 @@ public: static mme_gtpc* get_instance(); - bool init(srslte::log_filter* mme_gtpc_log); + bool init(); bool send_s11_pdu(const srslte::gtpc_pdu& pdu); void handle_s11_pdu(srslte::byte_buffer_t* msg); @@ -56,8 +56,8 @@ public: private: mme_gtpc() = default; - srslte::log_filter* m_mme_gtpc_log; - s1ap* m_s1ap; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("MME GTPC"); + s1ap* m_s1ap; uint32_t m_next_ctrl_teid; std::map m_mme_ctr_teid_to_imsi; diff --git a/srsepc/hdr/mme/nas.h b/srsepc/hdr/mme/nas.h index b528fe674..b91679874 100644 --- a/srsepc/hdr/mme/nas.h +++ b/srsepc/hdr/mme/nas.h @@ -18,6 +18,7 @@ #include "srslte/common/buffer_pool.h" #include "srslte/common/security.h" #include "srslte/interfaces/epc_interfaces.h" +#include "srslte/srslog/srslog.h" #include namespace srsepc { @@ -141,7 +142,7 @@ typedef struct { class nas { public: - nas(const nas_init_t& args, const nas_if_t& itf, srslte::log* nas_log); + nas(const nas_init_t& args, const nas_if_t& itf); void reset(); /*********************** @@ -152,16 +153,14 @@ public: struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); static bool handle_imsi_attach_request_unknown_ue(uint32_t enb_ue_s1ap_id, struct sctp_sndrcvinfo* enb_sri, const LIBLTE_MME_ATTACH_REQUEST_MSG_STRUCT& attach_req, const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); static bool handle_imsi_attach_request_known_ue(nas* nas_ctx, uint32_t enb_ue_s1ap_id, @@ -170,16 +169,14 @@ public: const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); static bool handle_guti_attach_request_unknown_ue(uint32_t enb_ue_s1ap_id, struct sctp_sndrcvinfo* enb_sri, const LIBLTE_MME_ATTACH_REQUEST_MSG_STRUCT& attach_req, const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); static bool handle_guti_attach_request_known_ue(nas* nas_ctx, uint32_t enb_ue_s1ap_id, @@ -188,8 +185,7 @@ public: const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); // Service request messages static bool handle_service_request(uint32_t m_tmsi, @@ -197,8 +193,7 @@ public: struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); // Dettach request messages static bool handle_detach_request(uint32_t m_tmsi, @@ -206,8 +201,7 @@ public: struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); // Tracking area update request messages static bool handle_tracking_area_update_request(uint32_t m_tmsi, @@ -215,8 +209,7 @@ public: struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log); + const nas_if_t& itf); /* Uplink NAS messages handling */ bool handle_attach_request(srslte::byte_buffer_t* nas_rx); @@ -258,12 +251,12 @@ public: sec_ctx_t m_sec_ctx = {}; private: - srslte::byte_buffer_pool* m_pool = nullptr; - srslte::log* m_nas_log = nullptr; - gtpc_interface_nas* m_gtpc = nullptr; - s1ap_interface_nas* m_s1ap = nullptr; - hss_interface_nas* m_hss = nullptr; - mme_interface_nas* m_mme = nullptr; + srslte::byte_buffer_pool* m_pool = nullptr; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("NAS"); + gtpc_interface_nas* m_gtpc = nullptr; + s1ap_interface_nas* m_s1ap = nullptr; + hss_interface_nas* m_hss = nullptr; + mme_interface_nas* m_mme = nullptr; uint16_t m_mcc = 0; uint16_t m_mnc = 0; diff --git a/srsepc/hdr/mme/s1ap.h b/srsepc/hdr/mme/s1ap.h index 08363d8ef..54a207818 100644 --- a/srsepc/hdr/mme/s1ap.h +++ b/srsepc/hdr/mme/s1ap.h @@ -27,6 +27,7 @@ #include "srslte/common/log.h" #include "srslte/common/s1ap_pcap.h" #include "srslte/interfaces/epc_interfaces.h" +#include "srslte/srslog/srslog.h" #include #include #include @@ -49,7 +50,7 @@ public: static void cleanup(); int enb_listen(); - int init(s1ap_args_t s1ap_args, srslte::log_filter* s1ap_log, srslte::log_filter* nas_log); + int init(s1ap_args_t s1ap_args); void stop(); int get_s1_mme(); @@ -86,9 +87,8 @@ public: uint32_t allocate_m_tmsi(uint64_t imsi); virtual uint64_t find_imsi_from_m_tmsi(uint32_t m_tmsi); - s1ap_args_t m_s1ap_args; - srslte::log_filter* m_s1ap_log; - srslte::log_filter* m_nas_log; + s1ap_args_t m_s1ap_args; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); s1ap_mngmt_proc* m_s1ap_mngmt_proc; s1ap_nas_transport* m_s1ap_nas_transport; diff --git a/srsepc/hdr/mme/s1ap_ctx_mngmt_proc.h b/srsepc/hdr/mme/s1ap_ctx_mngmt_proc.h index 70ae976c8..6774644f8 100644 --- a/srsepc/hdr/mme/s1ap_ctx_mngmt_proc.h +++ b/srsepc/hdr/mme/s1ap_ctx_mngmt_proc.h @@ -43,8 +43,8 @@ private: s1ap_ctx_mngmt_proc(); virtual ~s1ap_ctx_mngmt_proc(); - s1ap* m_s1ap; - srslte::log_filter* m_s1ap_log; + s1ap* m_s1ap; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); s1ap_args_t m_s1ap_args; diff --git a/srsepc/hdr/mme/s1ap_erab_mngmt_proc.h b/srsepc/hdr/mme/s1ap_erab_mngmt_proc.h index 10ba7ef2e..11612098a 100644 --- a/srsepc/hdr/mme/s1ap_erab_mngmt_proc.h +++ b/srsepc/hdr/mme/s1ap_erab_mngmt_proc.h @@ -48,8 +48,8 @@ private: s1ap_erab_mngmt_proc(); virtual ~s1ap_erab_mngmt_proc(); - s1ap* m_s1ap = nullptr; - srslte::log_filter* m_s1ap_log = nullptr; + s1ap* m_s1ap = nullptr; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); s1ap_args_t m_s1ap_args; diff --git a/srsepc/hdr/mme/s1ap_mngmt_proc.h b/srsepc/hdr/mme/s1ap_mngmt_proc.h index ffd7bfded..cf376990d 100644 --- a/srsepc/hdr/mme/s1ap_mngmt_proc.h +++ b/srsepc/hdr/mme/s1ap_mngmt_proc.h @@ -16,6 +16,7 @@ #include "srslte/asn1/s1ap.h" #include "srslte/common/common.h" #include "srslte/common/log_filter.h" +#include "srslte/srslog/srslog.h" namespace srsepc { @@ -41,8 +42,8 @@ private: s1ap_mngmt_proc(); virtual ~s1ap_mngmt_proc(); - s1ap* m_s1ap; - srslte::log_filter* m_s1ap_log; + s1ap* m_s1ap; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); int m_s1mme; s1ap_args_t m_s1ap_args; diff --git a/srsepc/hdr/mme/s1ap_nas_transport.h b/srsepc/hdr/mme/s1ap_nas_transport.h index 01feaf313..5c01b6979 100644 --- a/srsepc/hdr/mme/s1ap_nas_transport.h +++ b/srsepc/hdr/mme/s1ap_nas_transport.h @@ -40,7 +40,7 @@ private: s1ap_nas_transport(); virtual ~s1ap_nas_transport(); - srslte::log* m_s1ap_log; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); srslte::byte_buffer_pool* m_pool; s1ap* m_s1ap; diff --git a/srsepc/hdr/mme/s1ap_paging.h b/srsepc/hdr/mme/s1ap_paging.h index 755166291..ca0deb67b 100644 --- a/srsepc/hdr/mme/s1ap_paging.h +++ b/srsepc/hdr/mme/s1ap_paging.h @@ -16,6 +16,7 @@ #include "srslte/common/buffer_pool.h" #include "srslte/common/common.h" #include "srslte/common/log_filter.h" +#include "srslte/srslog/srslog.h" namespace srsepc { @@ -36,9 +37,9 @@ public: bool send_paging(uint64_t imsi, uint16_t erab_to_setup); private: - mme* m_mme; - s1ap* m_s1ap; - srslte::log_filter* m_s1ap_log; + mme* m_mme; + s1ap* m_s1ap; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("S1AP"); s1ap_args_t m_s1ap_args; srslte::byte_buffer_pool* m_pool; diff --git a/srsepc/hdr/spgw/gtpc.h b/srsepc/hdr/spgw/gtpc.h index b9ca7f262..c7a9d8025 100644 --- a/srsepc/hdr/spgw/gtpc.h +++ b/srsepc/hdr/spgw/gtpc.h @@ -15,6 +15,7 @@ #include "srsepc/hdr/spgw/spgw.h" #include "srslte/asn1/gtpc.h" #include "srslte/interfaces/epc_interfaces.h" +#include "srslte/srslog/srslog.h" #include #include #include @@ -26,11 +27,7 @@ class spgw::gtpc : public gtpc_interface_gtpu public: gtpc(); virtual ~gtpc(); - int init(spgw_args_t* args, - spgw* spgw, - gtpu_interface_gtpc* gtpu, - srslte::log_filter* gtpc_log, - const std::map& ip_to_imsi); + int init(spgw_args_t* args, spgw* spgw, gtpu_interface_gtpc* gtpu, const std::map& ip_to_imsi); void stop(); int init_s11(spgw_args_t* args); @@ -85,7 +82,7 @@ public: std::set m_ue_ip_addr_pool; std::map m_imsi_to_ip; - srslte::log_filter* m_gtpc_log; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("SPGW GTPC"); srslte::byte_buffer_pool* m_pool; }; diff --git a/srsepc/hdr/spgw/gtpu.h b/srsepc/hdr/spgw/gtpu.h index 928bb6759..7bcc7c5f3 100644 --- a/srsepc/hdr/spgw/gtpu.h +++ b/srsepc/hdr/spgw/gtpu.h @@ -18,6 +18,7 @@ #include "srslte/common/buffer_pool.h" #include "srslte/common/logmap.h" #include "srslte/interfaces/epc_interfaces.h" +#include "srslte/srslog/srslog.h" #include #include @@ -63,6 +64,8 @@ public: // UE is attached without an active user-plane // for downlink notifications. + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("GTPU"); + //:TODO: remove this once srslte common code loggers have been upgraded. srslte::log_ref m_gtpu_log; private: diff --git a/srsepc/hdr/spgw/spgw.h b/srsepc/hdr/spgw/spgw.h index 9a293a30a..f9f014dc7 100644 --- a/srsepc/hdr/spgw/spgw.h +++ b/srsepc/hdr/spgw/spgw.h @@ -24,6 +24,7 @@ #include "srslte/common/log_filter.h" #include "srslte/common/logmap.h" #include "srslte/common/threads.h" +#include "srslte/srslog/srslog.h" #include #include @@ -60,11 +61,7 @@ class spgw : public srslte::thread public: static spgw* get_instance(void); static void cleanup(void); - int init(spgw_args_t* args, - srslte::log_ref gtpu_log, - srslte::log_filter* gtpc_log, - srslte::log_filter* spgw_log, - const std::map& ip_to_imsi); + int init(spgw_args_t* args, srslte::log_ref gtpu_log, const std::map& ip_to_imsi); void stop(); void run_thread(); @@ -85,7 +82,7 @@ private: gtpu* m_gtpu; // Logs - srslte::log_filter* m_spgw_log; + srslog::basic_logger& m_logger = srslog::fetch_basic_logger("SPGW"); }; } // namespace srsepc diff --git a/srsepc/src/hss/hss.cc b/srsepc/src/hss/hss.cc index 1528dd062..8c6558c3a 100644 --- a/srsepc/src/hss/hss.cc +++ b/srsepc/src/hss/hss.cc @@ -54,11 +54,9 @@ void hss::cleanup() pthread_mutex_unlock(&hss_instance_mutex); } -int hss::init(hss_args_t* hss_args, srslte::log_filter* hss_log) +int hss::init(hss_args_t* hss_args) { srand(time(NULL)); - /*Init loggers*/ - m_hss_log = hss_log; /*Read user information from DB*/ if (read_db_file(hss_args->db_file) == false) { @@ -71,7 +69,7 @@ int hss::init(hss_args_t* hss_args, srslte::log_filter* hss_log) db_file = hss_args->db_file; - m_hss_log->info("HSS Initialized. DB file %s, MCC: %d, MNC: %d\n", hss_args->db_file.c_str(), mcc, mnc); + m_logger.info("HSS Initialized. DB file %s, MCC: %d, MNC: %d", hss_args->db_file.c_str(), mcc, mnc); srslte::console("HSS Initialized.\n"); return 0; } @@ -90,7 +88,7 @@ bool hss::read_db_file(std::string db_filename) if (!m_db_file.is_open()) { return false; } - m_hss_log->info("Opened DB file: %s\n", db_filename.c_str()); + m_logger.info("Opened DB file: %s", db_filename.c_str()); std::string line; while (std::getline(m_db_file, line)) { @@ -98,8 +96,8 @@ bool hss::read_db_file(std::string db_filename) uint column_size = 10; std::vector split = split_string(line, ','); if (split.size() != column_size) { - m_hss_log->error("Error parsing UE database. Wrong number of columns in .csv\n"); - m_hss_log->error("Columns: %zd, Expected %d.\n", split.size(), column_size); + m_logger.error("Error parsing UE database. Wrong number of columns in .csv"); + m_logger.error("Columns: %zd, Expected %d.", split.size(), column_size); srslte::console("\nError parsing UE database. Wrong number of columns in user database CSV.\n"); srslte::console("Perhaps you are using an old user_db.csv?\n"); @@ -113,7 +111,7 @@ bool hss::read_db_file(std::string db_filename) } else if (split[1] == std::string("mil")) { ue_ctx->algo = HSS_ALGO_MILENAGE; } else { - m_hss_log->error("Neither XOR nor MILENAGE configured.\n"); + m_logger.error("Neither XOR nor MILENAGE configured."); return false; } ue_ctx->imsi = strtoull(split[2].c_str(), nullptr, 10); @@ -126,22 +124,22 @@ bool hss::read_db_file(std::string db_filename) ue_ctx->op_configured = false; get_uint_vec_from_hex_str(split[5], ue_ctx->opc, 16); } else { - m_hss_log->error("Neither OP nor OPc configured.\n"); + m_logger.error("Neither OP nor OPc configured."); return false; } get_uint_vec_from_hex_str(split[6], ue_ctx->amf, 2); get_uint_vec_from_hex_str(split[7], ue_ctx->sqn, 6); - m_hss_log->debug("Added user from DB, IMSI: %015" PRIu64 "\n", ue_ctx->imsi); - m_hss_log->debug_hex(ue_ctx->key, 16, "User Key : "); + m_logger.debug("Added user from DB, IMSI: %015" PRIu64 "", ue_ctx->imsi); + m_logger.debug(ue_ctx->key, 16, "User Key : "); if (ue_ctx->op_configured) { - m_hss_log->debug_hex(ue_ctx->op, 16, "User OP : "); + m_logger.debug(ue_ctx->op, 16, "User OP : "); } - m_hss_log->debug_hex(ue_ctx->opc, 16, "User OPc : "); - m_hss_log->debug_hex(ue_ctx->amf, 2, "AMF : "); - m_hss_log->debug_hex(ue_ctx->sqn, 6, "SQN : "); + m_logger.debug(ue_ctx->opc, 16, "User OPc : "); + m_logger.debug(ue_ctx->amf, 2, "AMF : "); + m_logger.debug(ue_ctx->sqn, 6, "SQN : "); ue_ctx->qci = (uint16_t)strtol(split[8].c_str(), nullptr, 10); - m_hss_log->debug("Default Bearer QCI: %d\n", ue_ctx->qci); + m_logger.debug("Default Bearer QCI: %d", ue_ctx->qci); if (split[9] == std::string("dynamic")) { ue_ctx->static_ip_addr = "0.0.0.0"; @@ -150,13 +148,13 @@ bool hss::read_db_file(std::string db_filename) if (inet_pton(AF_INET, split[9].c_str(), buf)) { if (m_ip_to_imsi.insert(std::make_pair(split[9], ue_ctx->imsi)).second) { ue_ctx->static_ip_addr = split[9]; - m_hss_log->info("static ip addr %s\n", ue_ctx->static_ip_addr.c_str()); + m_logger.info("static ip addr %s", ue_ctx->static_ip_addr.c_str()); } else { - m_hss_log->info("duplicate static ip addr %s\n", split[9].c_str()); + m_logger.info("duplicate static ip addr %s", split[9].c_str()); return false; } } else { - m_hss_log->info("invalid static ip addr %s, %s\n", split[9].c_str(), strerror(errno)); + m_logger.info("invalid static ip addr %s, %s", split[9].c_str(), strerror(errno)); return false; } } @@ -185,7 +183,7 @@ bool hss::write_db_file(std::string db_filename) if (!m_db_file.is_open()) { return false; } - m_hss_log->info("Opened DB file: %s\n", db_filename.c_str()); + m_logger.info("Opened DB file: %s", db_filename.c_str()); // Write comment info m_db_file << "# \n" @@ -249,11 +247,11 @@ bool hss::write_db_file(std::string db_filename) bool hss::gen_auth_info_answer(uint64_t imsi, uint8_t* k_asme, uint8_t* autn, uint8_t* rand, uint8_t* xres) { - m_hss_log->debug("Generating AUTH info answer\n"); + m_logger.debug("Generating AUTH info answer"); hss_ue_ctx_t* ue_ctx = get_ue_ctx(imsi); if (ue_ctx == nullptr) { srslte::console("User not found at HSS. IMSI: %015" PRIu64 "\n", imsi); - m_hss_log->error("User not found at HSS. IMSI: %015" PRIu64 "\n", imsi); + m_logger.error("User not found at HSS. IMSI: %015" PRIu64 "", imsi); return false; } @@ -291,24 +289,24 @@ void hss::gen_auth_info_answer_milenage(hss_ue_ctx_t* ue_ctx, srslte::security_milenage_f2345(k, opc, rand, xres, ck, ik, ak); - m_hss_log->debug_hex(k, 16, "User Key : "); - m_hss_log->debug_hex(opc, 16, "User OPc : "); - m_hss_log->debug_hex(rand, 16, "User Rand : "); - m_hss_log->debug_hex(xres, 8, "User XRES: "); - m_hss_log->debug_hex(ck, 16, "User CK: "); - m_hss_log->debug_hex(ik, 16, "User IK: "); - m_hss_log->debug_hex(ak, 6, "User AK: "); + m_logger.debug(k, 16, "User Key : "); + m_logger.debug(opc, 16, "User OPc : "); + m_logger.debug(rand, 16, "User Rand : "); + m_logger.debug(xres, 8, "User XRES: "); + m_logger.debug(ck, 16, "User CK: "); + m_logger.debug(ik, 16, "User IK: "); + m_logger.debug(ak, 6, "User AK: "); srslte::security_milenage_f1(k, opc, rand, sqn, amf, mac); - m_hss_log->debug_hex(sqn, 6, "User SQN : "); - m_hss_log->debug_hex(mac, 8, "User MAC : "); + m_logger.debug(sqn, 6, "User SQN : "); + m_logger.debug(mac, 8, "User MAC : "); // Generate K_asme srslte::security_generate_k_asme(ck, ik, ak, sqn, mcc, mnc, k_asme); - m_hss_log->debug("User MCC : %x MNC : %x \n", mcc, mnc); - m_hss_log->debug_hex(k_asme, 32, "User k_asme : "); + m_logger.debug("User MCC : %x MNC : %x ", mcc, mnc); + m_logger.debug(k_asme, 32, "User k_asme : "); // Generate AUTN (autn = sqn ^ ak |+| amf |+| mac) for (int i = 0; i < 6; i++) { @@ -320,7 +318,7 @@ void hss::gen_auth_info_answer_milenage(hss_ue_ctx_t* ue_ctx, for (int i = 0; i < 8; i++) { autn[8 + i] = mac[i]; } - m_hss_log->debug_hex(autn, 16, "User AUTN: "); + m_logger.debug(autn, 16, "User AUTN: "); // Set last RAND ue_ctx->set_last_rand(rand); @@ -363,13 +361,13 @@ void hss::gen_auth_info_answer_xor(hss_ue_ctx_t* ue_ctx, uint8_t* k_asme, uint8_ ak[i] = xdout[i + 3]; } - m_hss_log->debug_hex(k, 16, "User Key : "); - m_hss_log->debug_hex(opc, 16, "User OPc : "); - m_hss_log->debug_hex(rand, 16, "User Rand : "); - m_hss_log->debug_hex(xres, 8, "User XRES: "); - m_hss_log->debug_hex(ck, 16, "User CK: "); - m_hss_log->debug_hex(ik, 16, "User IK: "); - m_hss_log->debug_hex(ak, 6, "User AK: "); + m_logger.debug(k, 16, "User Key : "); + m_logger.debug(opc, 16, "User OPc : "); + m_logger.debug(rand, 16, "User Rand : "); + m_logger.debug(xres, 8, "User XRES: "); + m_logger.debug(ck, 16, "User CK: "); + m_logger.debug(ik, 16, "User IK: "); + m_logger.debug(ak, 6, "User AK: "); // Generate cdout for (i = 0; i < 6; i++) { @@ -384,8 +382,8 @@ void hss::gen_auth_info_answer_xor(hss_ue_ctx_t* ue_ctx, uint8_t* k_asme, uint8_ mac[i] = xdout[i] ^ cdout[i]; } - m_hss_log->debug_hex(sqn, 6, "User SQN : "); - m_hss_log->debug_hex(mac, 8, "User MAC : "); + m_logger.debug(sqn, 6, "User SQN : "); + m_logger.debug(mac, 8, "User MAC : "); // Generate AUTN (autn = sqn ^ ak |+| amf |+| mac) for (int i = 0; i < 6; i++) { @@ -401,8 +399,8 @@ void hss::gen_auth_info_answer_xor(hss_ue_ctx_t* ue_ctx, uint8_t* k_asme, uint8_ // Generate K_asme srslte::security_generate_k_asme(ck, ik, ak, sqn, mcc, mnc, k_asme); - m_hss_log->debug("User MCC : %x MNC : %x \n", mcc, mnc); - m_hss_log->debug_hex(k_asme, 32, "User k_asme : "); + m_logger.debug("User MCC : %x MNC : %x ", mcc, mnc); + m_logger.debug(k_asme, 32, "User k_asme : "); // Generate AUTN (autn = sqn ^ ak |+| amf |+| mac) for (int i = 0; i < 6; i++) { @@ -415,7 +413,7 @@ void hss::gen_auth_info_answer_xor(hss_ue_ctx_t* ue_ctx, uint8_t* k_asme, uint8_ autn[8 + i] = mac[i]; } - m_hss_log->debug_hex(autn, 8, "User AUTN: "); + m_logger.debug(autn, 8, "User AUTN: "); // Set last RAND ue_ctx->set_last_rand(rand); @@ -426,23 +424,23 @@ bool hss::gen_update_loc_answer(uint64_t imsi, uint8_t* qci) { std::map >::iterator ue_ctx_it = m_imsi_to_ue_ctx.find(imsi); if (ue_ctx_it == m_imsi_to_ue_ctx.end()) { - m_hss_log->info("User not found. IMSI: %015" PRIu64 "\n", imsi); + m_logger.info("User not found. IMSI: %015" PRIu64 "", imsi); srslte::console("User not found at HSS. IMSI: %015" PRIu64 "\n", imsi); return false; } const std::unique_ptr& ue_ctx = ue_ctx_it->second; - m_hss_log->info("Found User %015" PRIu64 "\n", imsi); + m_logger.info("Found User %015" PRIu64 "", imsi); *qci = ue_ctx->qci; return true; } bool hss::resync_sqn(uint64_t imsi, uint8_t* auts) { - m_hss_log->debug("Re-syncing SQN\n"); + m_logger.debug("Re-syncing SQN"); hss_ue_ctx_t* ue_ctx = get_ue_ctx(imsi); if (ue_ctx == nullptr) { srslte::console("User not found at HSS. IMSI: %015" PRIu64 "\n", imsi); - m_hss_log->error("User not found at HSS. IMSI: %015" PRIu64 "\n", imsi); + m_logger.error("User not found at HSS. IMSI: %015" PRIu64 "", imsi); return false; } @@ -461,7 +459,7 @@ bool hss::resync_sqn(uint64_t imsi, uint8_t* auts) void hss::resync_sqn_xor(hss_ue_ctx_t* ue_ctx, uint8_t* auts) { - m_hss_log->error("XOR SQN synchronization not supported yet\n"); + m_logger.error("XOR SQN synchronization not supported yet"); srslte::console("XOR SQNs synchronization not supported yet\n"); return; } @@ -490,30 +488,30 @@ void hss::resync_sqn_milenage(hss_ue_ctx_t* ue_ctx, uint8_t* auts) mac_s[i] = auts[i + 6]; } - m_hss_log->debug_hex(k, 16, "User Key : "); - m_hss_log->debug_hex(opc, 16, "User OPc : "); - m_hss_log->debug_hex(amf, 2, "User AMF : "); - m_hss_log->debug_hex(last_rand, 16, "User Last Rand : "); - m_hss_log->debug_hex(auts, 16, "AUTS : "); - m_hss_log->debug_hex(sqn_ms_xor_ak, 6, "SQN xor AK : "); - m_hss_log->debug_hex(mac_s, 8, "MAC : "); + m_logger.debug(k, 16, "User Key : "); + m_logger.debug(opc, 16, "User OPc : "); + m_logger.debug(amf, 2, "User AMF : "); + m_logger.debug(last_rand, 16, "User Last Rand : "); + m_logger.debug(auts, 16, "AUTS : "); + m_logger.debug(sqn_ms_xor_ak, 6, "SQN xor AK : "); + m_logger.debug(mac_s, 8, "MAC : "); srslte::security_milenage_f5_star(k, opc, last_rand, ak); - m_hss_log->debug_hex(ak, 6, "Resynch AK : "); + m_logger.debug(ak, 6, "Resynch AK : "); uint8_t sqn_ms[6]; for (int i = 0; i < 6; i++) { sqn_ms[i] = sqn_ms_xor_ak[i] ^ ak[i]; } - m_hss_log->debug_hex(sqn_ms, 6, "SQN MS : "); - m_hss_log->debug_hex(sqn, 6, "SQN HE : "); + m_logger.debug(sqn_ms, 6, "SQN MS : "); + m_logger.debug(sqn, 6, "SQN HE : "); uint8_t mac_s_tmp[8]; uint8_t dummy_amf[2] = {}; srslte::security_milenage_f1_star(k, opc, last_rand, sqn_ms, dummy_amf, mac_s_tmp); - m_hss_log->debug_hex(mac_s_tmp, 8, "MAC calc : "); + m_logger.debug(mac_s_tmp, 8, "MAC calc : "); ue_ctx->set_sqn(sqn_ms); return; @@ -522,8 +520,8 @@ void hss::resync_sqn_milenage(hss_ue_ctx_t* ue_ctx, uint8_t* auts) void hss::increment_ue_sqn(hss_ue_ctx_t* ue_ctx) { increment_sqn(ue_ctx->sqn, ue_ctx->sqn); - m_hss_log->debug("Incremented SQN -- IMSI: %015" PRIu64 "\n", ue_ctx->imsi); - m_hss_log->debug_hex(ue_ctx->sqn, 6, "SQN: "); + m_logger.debug("Incremented SQN -- IMSI: %015" PRIu64 "", ue_ctx->imsi); + m_logger.debug(ue_ctx->sqn, 6, "SQN: "); } void hss::increment_sqn(uint8_t* sqn, uint8_t* next_sqn) @@ -598,7 +596,7 @@ hss_ue_ctx_t* hss::get_ue_ctx(uint64_t imsi) { std::map >::iterator ue_ctx_it = m_imsi_to_ue_ctx.find(imsi); if (ue_ctx_it == m_imsi_to_ue_ctx.end()) { - m_hss_log->info("User not found. IMSI: %015" PRIu64 "\n", imsi); + m_logger.info("User not found. IMSI: %015" PRIu64 "", imsi); return nullptr; } diff --git a/srsepc/src/main.cc b/srsepc/src/main.cc index e6a4abccb..5830ace2c 100644 --- a/srsepc/src/main.cc +++ b/srsepc/src/main.cc @@ -391,14 +391,14 @@ int main(int argc, char* argv[]) return SRSLTE_ERROR; } srslte::srslog_wrapper log_wrapper(*chan); + srslog::set_default_sink(*log_sink); // Start the log backend. srslog::init(); if (args.log_args.filename != "stdout") { - log_wrapper.log_char("\n\n"); - log_wrapper.log_char(get_build_string().c_str()); - log_wrapper.log_char("\n--- Software Radio Systems EPC log ---\n\n"); + auto& epc_logger = srslog::fetch_basic_logger("EPC", false); + epc_logger.info("\n\n%s\n--- Software Radio Systems EPC log ---\n\n", get_build_string().c_str()); } srslte::logmap::set_default_logger(&log_wrapper); @@ -408,50 +408,71 @@ int main(int argc, char* argv[]) nas_log.init("NAS ", &log_wrapper); nas_log.set_level(level(args.log_args.nas_level)); nas_log.set_hex_limit(args.log_args.nas_hex_limit); + auto& nas_logger = srslog::fetch_basic_logger("NAS", false); + nas_logger.set_level(srslog::str_to_basic_level(args.log_args.nas_level)); + nas_logger.set_hex_dump_max_size(args.log_args.nas_hex_limit); srslte::log_filter s1ap_log; s1ap_log.init("S1AP", &log_wrapper); s1ap_log.set_level(level(args.log_args.s1ap_level)); s1ap_log.set_hex_limit(args.log_args.s1ap_hex_limit); + auto& s1ap_logger = srslog::fetch_basic_logger("S1AP", false); + s1ap_logger.set_level(srslog::str_to_basic_level(args.log_args.s1ap_level)); + s1ap_logger.set_hex_dump_max_size(args.log_args.s1ap_hex_limit); srslte::log_filter mme_gtpc_log; mme_gtpc_log.init("MME GTPC", &log_wrapper); mme_gtpc_log.set_level(level(args.log_args.mme_gtpc_level)); mme_gtpc_log.set_hex_limit(args.log_args.mme_gtpc_hex_limit); + auto& mme_gtpc_logger = srslog::fetch_basic_logger("MME GTPC", false); + mme_gtpc_logger.set_level(srslog::str_to_basic_level(args.log_args.mme_gtpc_level)); + mme_gtpc_logger.set_hex_dump_max_size(args.log_args.mme_gtpc_hex_limit); srslte::log_filter hss_log; hss_log.init("HSS ", &log_wrapper); hss_log.set_level(level(args.log_args.hss_level)); hss_log.set_hex_limit(args.log_args.hss_hex_limit); + auto& hss_logger = srslog::fetch_basic_logger("HSS", false); + hss_logger.set_level(srslog::str_to_basic_level(args.log_args.hss_level)); + hss_logger.set_hex_dump_max_size(args.log_args.hss_hex_limit); srslte::log_filter spgw_gtpc_log; spgw_gtpc_log.init("SPGW GTPC", &log_wrapper); spgw_gtpc_log.set_level(level(args.log_args.spgw_gtpc_level)); spgw_gtpc_log.set_hex_limit(args.log_args.spgw_gtpc_hex_limit); + auto& spgw_gtpc_logger = srslog::fetch_basic_logger("SPGW GTPC", false); + spgw_gtpc_logger.set_level(srslog::str_to_basic_level(args.log_args.spgw_gtpc_level)); + spgw_gtpc_logger.set_hex_dump_max_size(args.log_args.spgw_gtpc_hex_limit); srslte::log_ref gtpu_log{"GTPU"}; gtpu_log->set_level(level(args.log_args.mme_gtpc_level)); gtpu_log->set_hex_limit(args.log_args.mme_gtpc_hex_limit); + auto& gtpu_logger = srslog::fetch_basic_logger("GTPU", false); + gtpu_logger.set_level(srslog::str_to_basic_level(args.log_args.gtpu_level)); + gtpu_logger.set_hex_dump_max_size(args.log_args.gtpu_hex_limit); srslte::log_filter spgw_log; spgw_log.init("SPGW", &log_wrapper); spgw_log.set_level(level(args.log_args.spgw_level)); spgw_log.set_hex_limit(args.log_args.spgw_hex_limit); + auto& spgw_logger = srslog::fetch_basic_logger("SPGW", false); + spgw_logger.set_level(srslog::str_to_basic_level(args.log_args.spgw_level)); + spgw_logger.set_hex_dump_max_size(args.log_args.spgw_hex_limit); hss* hss = hss::get_instance(); - if (hss->init(&args.hss_args, &hss_log)) { + if (hss->init(&args.hss_args)) { cout << "Error initializing HSS" << endl; exit(1); } mme* mme = mme::get_instance(); - if (mme->init(&args.mme_args, &nas_log, &s1ap_log, &mme_gtpc_log)) { + if (mme->init(&args.mme_args)) { cout << "Error initializing MME" << endl; exit(1); } spgw* spgw = spgw::get_instance(); - if (spgw->init(&args.spgw_args, gtpu_log, &spgw_gtpc_log, &spgw_log, hss->get_ip_to_imsi())) { + if (spgw->init(&args.spgw_args, gtpu_log, hss->get_ip_to_imsi())) { cout << "Error initializing SP-GW" << endl; exit(1); } diff --git a/srsepc/src/mbms-gw/main.cc b/srsepc/src/mbms-gw/main.cc index ffcec3ba9..53494570d 100644 --- a/srsepc/src/mbms-gw/main.cc +++ b/srsepc/src/mbms-gw/main.cc @@ -196,12 +196,14 @@ int main(int argc, char* argv[]) return SRSLTE_ERROR; } srslte::srslog_wrapper log_wrapper(*chan); + srslog::set_default_sink(*log_sink); // Start the log backend. srslog::init(); if (args.log_args.filename != "stdout") { - log_wrapper.log_char("\n--- Software Radio Systems MBMS log ---\n\n"); + auto& mbms_gw_logger = srslog::fetch_basic_logger("MBMS GW", false); + mbms_gw_logger.info("\n--- Software Radio Systems MBMS log ---\n\n"); } srslte::logmap::set_default_logger(&log_wrapper); @@ -209,6 +211,9 @@ int main(int argc, char* argv[]) srslte::log_ref mbms_gw_log{"MBMS"}; mbms_gw_log->set_level(level(args.log_args.mbms_gw_level)); mbms_gw_log->set_hex_limit(args.log_args.mbms_gw_hex_limit); + auto& mbms_gw_logger = srslog::fetch_basic_logger("MBMS", false); + mbms_gw_logger.set_level(srslog::str_to_basic_level(args.log_args.mbms_gw_level)); + mbms_gw_logger.set_hex_dump_max_size(args.log_args.mbms_gw_hex_limit); mbms_gw* mbms_gw = mbms_gw::get_instance(); if (mbms_gw->init(&args.mbms_gw_args, mbms_gw_log)) { diff --git a/srsepc/src/mbms-gw/mbms-gw.cc b/srsepc/src/mbms-gw/mbms-gw.cc index f9e6bfc45..d7f916116 100644 --- a/srsepc/src/mbms-gw/mbms-gw.cc +++ b/srsepc/src/mbms-gw/mbms-gw.cc @@ -71,16 +71,16 @@ int mbms_gw::init(mbms_gw_args_t* args, srslte::log_ref mbms_gw_log) err = init_sgi_mb_if(args); if (err != SRSLTE_SUCCESS) { srslte::console("Error initializing SGi-MB.\n"); - m_mbms_gw_log->error("Error initializing SGi-MB.\n"); + m_logger.error("Error initializing SGi-MB."); return SRSLTE_ERROR_CANT_START; } err = init_m1_u(args); if (err != SRSLTE_SUCCESS) { srslte::console("Error initializing SGi-MB.\n"); - m_mbms_gw_log->error("Error initializing SGi-MB.\n"); + m_logger.error("Error initializing SGi-MB."); return SRSLTE_ERROR_CANT_START; } - m_mbms_gw_log->info("MBMS GW Initiated\n"); + m_logger.info("MBMS GW Initiated"); srslte::console("MBMS GW Initiated\n"); return SRSLTE_SUCCESS; } @@ -90,7 +90,7 @@ void mbms_gw::stop() if (m_running) { if (m_sgi_mb_up) { close(m_sgi_mb_if); - m_mbms_gw_log->info("Closed SGi-MB interface\n"); + m_logger.info("Closed SGi-MB interface"); } m_running = false; thread_cancel(); @@ -109,9 +109,9 @@ int mbms_gw::init_sgi_mb_if(mbms_gw_args_t* args) // Construct the TUN device m_sgi_mb_if = open("/dev/net/tun", O_RDWR); - m_mbms_gw_log->info("TUN file descriptor = %d\n", m_sgi_mb_if); + m_logger.info("TUN file descriptor = %d", m_sgi_mb_if); if (m_sgi_mb_if < 0) { - m_mbms_gw_log->error("Failed to open TUN device: %s\n", strerror(errno)); + m_logger.error("Failed to open TUN device: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } @@ -123,23 +123,23 @@ int mbms_gw::init_sgi_mb_if(mbms_gw_args_t* args) ifr.ifr_ifrn.ifrn_name[IFNAMSIZ - 1] = '\0'; if (ioctl(m_sgi_mb_if, TUNSETIFF, &ifr) < 0) { - m_mbms_gw_log->error("Failed to set TUN device name: %s\n", strerror(errno)); + m_logger.error("Failed to set TUN device name: %s", strerror(errno)); close(m_sgi_mb_if); return SRSLTE_ERROR_CANT_START; } else { - m_mbms_gw_log->debug("Set TUN device name: %s\n", args->sgi_mb_if_name.c_str()); + m_logger.debug("Set TUN device name: %s", args->sgi_mb_if_name.c_str()); } // Bring up the interface int sgi_mb_sock = socket(AF_INET, SOCK_DGRAM, 0); if (sgi_mb_sock < 0) { - m_mbms_gw_log->error("Failed to bring up socket: %s\n", strerror(errno)); + m_logger.error("Failed to bring up socket: %s", strerror(errno)); close(m_sgi_mb_if); return SRSLTE_ERROR_CANT_START; } if (ioctl(sgi_mb_sock, SIOCGIFFLAGS, &ifr) < 0) { - m_mbms_gw_log->error("Failed to bring up interface: %s\n", strerror(errno)); + m_logger.error("Failed to bring up interface: %s", strerror(errno)); close(m_sgi_mb_if); close(sgi_mb_sock); return SRSLTE_ERROR_CANT_START; @@ -147,7 +147,7 @@ int mbms_gw::init_sgi_mb_if(mbms_gw_args_t* args) ifr.ifr_flags |= IFF_UP | IFF_RUNNING; if (ioctl(sgi_mb_sock, SIOCSIFFLAGS, &ifr) < 0) { - m_mbms_gw_log->error("Failed to set socket flags: %s\n", strerror(errno)); + m_logger.error("Failed to set socket flags: %s", strerror(errno)); close(sgi_mb_sock); close(m_sgi_mb_if); return SRSLTE_ERROR_CANT_START; @@ -160,8 +160,8 @@ int mbms_gw::init_sgi_mb_if(mbms_gw_args_t* args) addr->sin_port = 0; if (ioctl(sgi_mb_sock, SIOCSIFADDR, &ifr) < 0) { - m_mbms_gw_log->error( - "Failed to set TUN interface IP. Address: %s, Error: %s\n", args->sgi_mb_if_addr.c_str(), strerror(errno)); + m_logger.error( + "Failed to set TUN interface IP. Address: %s, Error: %s", args->sgi_mb_if_addr.c_str(), strerror(errno)); close(m_sgi_mb_if); close(sgi_mb_sock); return SRSLTE_ERROR_CANT_START; @@ -170,7 +170,7 @@ int mbms_gw::init_sgi_mb_if(mbms_gw_args_t* args) ifr.ifr_netmask.sa_family = AF_INET; ((struct sockaddr_in*)&ifr.ifr_netmask)->sin_addr.s_addr = inet_addr(args->sgi_mb_if_mask.c_str()); if (ioctl(sgi_mb_sock, SIOCSIFNETMASK, &ifr) < 0) { - m_mbms_gw_log->error("Failed to set TUN interface Netmask. Error: %s\n", strerror(errno)); + m_logger.error("Failed to set TUN interface Netmask. Error: %s", strerror(errno)); close(m_sgi_mb_if); close(sgi_mb_sock); return SRSLTE_ERROR_CANT_START; @@ -187,7 +187,7 @@ int mbms_gw::init_m1_u(mbms_gw_args_t* args) struct sockaddr_in addr; m_m1u = socket(AF_INET, SOCK_DGRAM, 0); if (m_m1u < 0) { - m_mbms_gw_log->error("Failed to open socket: %s\n", strerror(errno)); + m_logger.error("Failed to open socket: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } m_m1u_up = true; @@ -195,10 +195,10 @@ int mbms_gw::init_m1_u(mbms_gw_args_t* args) /* set no loopback */ char loopch = 0; if (setsockopt(m_m1u, IPPROTO_IP, IP_MULTICAST_LOOP, (char*)&loopch, sizeof(char)) < 0) { - m_mbms_gw_log->error("Failed to disable loopback: %s\n", strerror(errno)); + m_logger.error("Failed to disable loopback: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } else { - m_mbms_gw_log->debug("Loopback disabled\n"); + m_logger.debug("Loopback disabled"); } /* Set local interface for outbound multicast packets*/ @@ -206,7 +206,7 @@ int mbms_gw::init_m1_u(mbms_gw_args_t* args) struct in_addr local_if; local_if.s_addr = inet_addr(args->m1u_multi_if.c_str()); if (setsockopt(m_m1u, IPPROTO_IP, IP_MULTICAST_IF, (char*)&local_if, sizeof(struct in_addr)) < 0) { - m_mbms_gw_log->error("Error %s setting multicast interface %s.\n", strerror(errno), args->m1u_multi_if.c_str()); + m_logger.error("Error %s setting multicast interface %s.", strerror(errno), args->m1u_multi_if.c_str()); return SRSLTE_ERROR_CANT_START; } else { printf("Multicast interface specified. Address: %s\n", args->m1u_multi_if.c_str()); @@ -222,7 +222,7 @@ int mbms_gw::init_m1_u(mbms_gw_args_t* args) m_m1u_multi_addr.sin_family = AF_INET; m_m1u_multi_addr.sin_port = htons(GTPU_RX_PORT + 1); m_m1u_multi_addr.sin_addr.s_addr = inet_addr(args->m1u_multi_addr.c_str()); - m_mbms_gw_log->info("Initialized M1-U\n"); + m_logger.info("Initialized M1-U"); return SRSLTE_SUCCESS; } @@ -243,7 +243,7 @@ void mbms_gw::run_thread() } while (n == -1 && errno == EAGAIN); if (n < 0) { - m_mbms_gw_log->error("Error reading from TUN interface. Error: %s\n", strerror(errno)); + m_logger.error("Error reading from TUN interface. Error: %s", strerror(errno)); } else { msg->N_bytes = n; handle_sgi_md_pdu(msg); @@ -266,14 +266,14 @@ void mbms_gw::handle_sgi_md_pdu(srslte::byte_buffer_t* msg) // Sanity Check IP packet if (msg->N_bytes < 20) { - m_mbms_gw_log->error("IPv4 min len: %d, drop msg len %d\n", 20, msg->N_bytes); + m_logger.error("IPv4 min len: %d, drop msg len %d", 20, msg->N_bytes); return; } // IP Headers struct iphdr* iph = (struct iphdr*)msg->msg; if (iph->version != 4) { - m_mbms_gw_log->info("IPv6 not supported yet.\n"); + m_logger.info("IPv6 not supported yet."); return; } @@ -286,7 +286,7 @@ void mbms_gw::handle_sgi_md_pdu(srslte::byte_buffer_t* msg) if (n < 0) { srslte::console("Error writing to M1-U socket.\n"); } else { - m_mbms_gw_log->debug("Sent %d Bytes\n", msg->N_bytes); + m_logger.debug("Sent %d Bytes", msg->N_bytes); } } diff --git a/srsepc/src/mme/mme.cc b/srsepc/src/mme/mme.cc index 2bfe299f5..894393189 100644 --- a/srsepc/src/mme/mme.cc +++ b/srsepc/src/mme/mme.cc @@ -53,32 +53,24 @@ void mme::cleanup(void) pthread_mutex_unlock(&mme_instance_mutex); } -int mme::init(mme_args_t* args, - srslte::log_filter* nas_log, - srslte::log_filter* s1ap_log, - srslte::log_filter* mme_gtpc_log) +int mme::init(mme_args_t* args) { - /*Init logger*/ - m_nas_log = nas_log; - m_s1ap_log = s1ap_log; - m_mme_gtpc_log = mme_gtpc_log; - /*Init S1AP*/ m_s1ap = s1ap::get_instance(); - if (m_s1ap->init(args->s1ap_args, nas_log, s1ap_log)) { - m_s1ap_log->error("Error initializing MME S1APP\n"); + if (m_s1ap->init(args->s1ap_args)) { + m_s1ap_logger.error("Error initializing MME S1APP"); exit(-1); } /*Init GTP-C*/ m_mme_gtpc = mme_gtpc::get_instance(); - if (!m_mme_gtpc->init(m_mme_gtpc_log)) { + if (!m_mme_gtpc->init()) { srslte::console("Error initializing GTP-C\n"); exit(-1); } /*Log successful initialization*/ - m_s1ap_log->info("MME Initialized. MCC: 0x%x, MNC: 0x%x\n", args->s1ap_args.mcc, args->s1ap_args.mnc); + m_s1ap_logger.info("MME Initialized. MCC: 0x%x, MNC: 0x%x", args->s1ap_args.mcc, args->s1ap_args.mnc); srslte::console("MME Initialized. MCC: 0x%x, MNC: 0x%x\n", args->s1ap_args.mcc, args->s1ap_args.mnc); return 0; } @@ -126,35 +118,35 @@ void mme::run_thread() for (std::vector::iterator it = timers.begin(); it != timers.end(); ++it) { FD_SET(it->fd, &m_set); max_fd = std::max(max_fd, it->fd); - m_s1ap_log->debug("Adding Timer fd %d to fd_set\n", it->fd); + m_s1ap_logger.debug("Adding Timer fd %d to fd_set", it->fd); } - m_s1ap_log->debug("Waiting for S1-MME or S11 Message\n"); + m_s1ap_logger.debug("Waiting for S1-MME or S11 Message"); int n = select(max_fd + 1, &m_set, NULL, NULL, NULL); if (n == -1) { - m_s1ap_log->error("Error from select\n"); + m_s1ap_logger.error("Error from select"); } else if (n) { // Handle S1-MME if (FD_ISSET(s1mme, &m_set)) { rd_sz = sctp_recvmsg(s1mme, pdu->msg, sz, (struct sockaddr*)&enb_addr, &fromlen, &sri, &msg_flags); if (rd_sz == -1 && errno != EAGAIN) { - m_s1ap_log->error("Error reading from SCTP socket: %s", strerror(errno)); + m_s1ap_logger.error("Error reading from SCTP socket: %s", strerror(errno)); } else if (rd_sz == -1 && errno == EAGAIN) { - m_s1ap_log->debug("Socket timeout reached"); + m_s1ap_logger.debug("Socket timeout reached"); } else { if (msg_flags & MSG_NOTIFICATION) { // Received notification union sctp_notification* notification = (union sctp_notification*)pdu->msg; - m_s1ap_log->debug("SCTP Notification %d\n", notification->sn_header.sn_type); + m_s1ap_logger.debug("SCTP Notification %d", notification->sn_header.sn_type); if (notification->sn_header.sn_type == SCTP_SHUTDOWN_EVENT) { - m_s1ap_log->info("SCTP Association Shutdown. Association: %d\n", sri.sinfo_assoc_id); + m_s1ap_logger.info("SCTP Association Shutdown. Association: %d", sri.sinfo_assoc_id); srslte::console("SCTP Association Shutdown. Association: %d\n", sri.sinfo_assoc_id); m_s1ap->delete_enb_ctx(sri.sinfo_assoc_id); } } else { // Received data pdu->N_bytes = rd_sz; - m_s1ap_log->info("Received S1AP msg. Size: %d\n", pdu->N_bytes); + m_s1ap_logger.info("Received S1AP msg. Size: %d", pdu->N_bytes); m_s1ap->handle_s1ap_rx_pdu(pdu, &sri); } } @@ -167,7 +159,7 @@ void mme::run_thread() // Handle NAS Timers for (std::vector::iterator it = timers.begin(); it != timers.end();) { if (FD_ISSET(it->fd, &m_set)) { - m_s1ap_log->info("Timer expired\n"); + m_s1ap_logger.info("Timer expired"); uint64_t exp; rd_sz = read(it->fd, &exp, sizeof(uint64_t)); m_s1ap->expire_nas_timer(it->type, it->imsi); @@ -178,7 +170,7 @@ void mme::run_thread() } } } else { - m_s1ap_log->debug("No data from select.\n"); + m_s1ap_logger.debug("No data from select."); } } return; @@ -189,7 +181,7 @@ void mme::run_thread() */ bool mme::add_nas_timer(int timer_fd, nas_timer_type type, uint64_t imsi) { - m_s1ap_log->debug("Adding NAS timer to MME. IMSI %" PRIu64 ", Type %d, Fd: %d\n", imsi, type, timer_fd); + m_s1ap_logger.debug("Adding NAS timer to MME. IMSI %" PRIu64 ", Type %d, Fd: %d", imsi, type, timer_fd); mme_timer_t timer; timer.fd = timer_fd; @@ -220,12 +212,12 @@ bool mme::remove_nas_timer(nas_timer_type type, uint64_t imsi) } } if (it == timers.end()) { - m_s1ap_log->warning("Could not find timer to remove. IMSI %" PRIu64 ", Type %d\n", imsi, type); + m_s1ap_logger.warning("Could not find timer to remove. IMSI %" PRIu64 ", Type %d", imsi, type); return false; } // removing timer - m_s1ap_log->debug("Removing NAS timer from MME. IMSI %" PRIu64 ", Type %d, Fd: %d\n", imsi, type, it->fd); + m_s1ap_logger.debug("Removing NAS timer from MME. IMSI %" PRIu64 ", Type %d, Fd: %d", imsi, type, it->fd); FD_CLR(it->fd, &m_set); close(it->fd); timers.erase(it); diff --git a/srsepc/src/mme/mme_gtpc.cc b/srsepc/src/mme/mme_gtpc.cc index 699854b97..6d87f2bbd 100644 --- a/srsepc/src/mme/mme_gtpc.cc +++ b/srsepc/src/mme/mme_gtpc.cc @@ -24,21 +24,18 @@ mme_gtpc* mme_gtpc::get_instance() return instance.get(); } -bool mme_gtpc::init(srslte::log_filter* mme_gtpc_log) +bool mme_gtpc::init() { - /*Init log*/ - m_mme_gtpc_log = mme_gtpc_log; - m_next_ctrl_teid = 1; m_s1ap = s1ap::get_instance(); if (!init_s11()) { - m_mme_gtpc_log->error("Error Initializing MME S11 Interface\n"); + m_logger.error("Error Initializing MME S11 Interface"); return false; } - m_mme_gtpc_log->info("MME GTP-C Initialized\n"); + m_logger.info("MME GTP-C Initialized"); srslte::console("MME GTP-C Initialized\n"); return true; } @@ -51,12 +48,12 @@ bool mme_gtpc::init_s11() char spgw_addr_name[] = "@spgw_s11"; // Logs - m_mme_gtpc_log->info("Initializing MME S11 interface.\n"); + m_logger.info("Initializing MME S11 interface."); // Open Socket m_s11 = socket(AF_UNIX, SOCK_DGRAM, 0); if (m_s11 < 0) { - m_mme_gtpc_log->error("Error opening UNIX socket. Error %s\n", strerror(errno)); + m_logger.error("Error opening UNIX socket. Error %s", strerror(errno)); return false; } @@ -68,7 +65,7 @@ bool mme_gtpc::init_s11() // Bind socket to address if (bind(m_s11, (const struct sockaddr*)&m_mme_addr, sizeof(m_mme_addr)) == -1) { - m_mme_gtpc_log->error("Error binding UNIX socket. Error %s\n", strerror(errno)); + m_logger.error("Error binding UNIX socket. Error %s", strerror(errno)); return false; } @@ -78,7 +75,7 @@ bool mme_gtpc::init_s11() snprintf(m_spgw_addr.sun_path, sizeof(m_spgw_addr.sun_path), "%s", spgw_addr_name); m_spgw_addr.sun_path[0] = '\0'; - m_mme_gtpc_log->info("MME S11 Initialized\n"); + m_logger.info("MME S11 Initialized"); srslte::console("MME S11 Initialized\n"); return true; } @@ -86,28 +83,28 @@ bool mme_gtpc::init_s11() bool mme_gtpc::send_s11_pdu(const srslte::gtpc_pdu& pdu) { int n; - m_mme_gtpc_log->debug("Sending S-11 GTP-C PDU\n"); + m_logger.debug("Sending S-11 GTP-C PDU"); // TODO Add GTP-C serialization code // Send S11 message to SPGW n = sendto(m_s11, &pdu, sizeof(pdu), 0, (const sockaddr*)&m_spgw_addr, sizeof(m_spgw_addr)); if (n < 0) { - m_mme_gtpc_log->error("Error sending to socket. Error %s\n", strerror(errno)); + m_logger.error("Error sending to socket. Error %s", strerror(errno)); srslte::console("Error sending to socket. Error %s\n", strerror(errno)); return false; } else { - m_mme_gtpc_log->debug("MME S11 Sent %d Bytes.\n", n); + m_logger.debug("MME S11 Sent %d Bytes.", n); } return true; } void mme_gtpc::handle_s11_pdu(srslte::byte_buffer_t* msg) { - m_mme_gtpc_log->debug("Received S11 message\n"); + m_logger.debug("Received S11 message"); srslte::gtpc_pdu* pdu; pdu = (srslte::gtpc_pdu*)msg->msg; - m_mme_gtpc_log->debug("MME Received GTP-C PDU. Message type %s\n", srslte::gtpc_msg_type_to_str(pdu->header.type)); + m_logger.debug("MME Received GTP-C PDU. Message type %s", srslte::gtpc_msg_type_to_str(pdu->header.type)); switch (pdu->header.type) { case srslte::GTPC_MSG_TYPE_CREATE_SESSION_RESPONSE: handle_create_session_response(pdu); @@ -119,14 +116,14 @@ void mme_gtpc::handle_s11_pdu(srslte::byte_buffer_t* msg) handle_downlink_data_notification(pdu); break; default: - m_mme_gtpc_log->error("Unhandled GTP-C Message type\n"); + m_logger.error("Unhandled GTP-C Message type"); } return; } bool mme_gtpc::send_create_session_request(uint64_t imsi) { - m_mme_gtpc_log->info("Sending Create Session Request.\n"); + m_logger.info("Sending Create Session Request."); srslte::console("Sending Create Session Request.\n"); struct srslte::gtpc_pdu cs_req_pdu; // Initialize GTP-C message to zero @@ -145,8 +142,8 @@ bool mme_gtpc::send_create_session_request(uint64_t imsi) // Control TEID allocated cs_req->sender_f_teid.teid = get_new_ctrl_teid(); - m_mme_gtpc_log->info("Next MME control TEID: %d\n", m_next_ctrl_teid); - m_mme_gtpc_log->info("Allocated MME control TEID: %d\n", cs_req->sender_f_teid.teid); + m_logger.info("Next MME control TEID: %d", m_next_ctrl_teid); + m_logger.info("Allocated MME control TEID: %d", cs_req->sender_f_teid.teid); srslte::console("Creating Session Response -- IMSI: %" PRIu64 "\n", imsi); srslte::console("Creating Session Response -- MME control TEID: %d\n", cs_req->sender_f_teid.teid); @@ -163,12 +160,11 @@ bool mme_gtpc::send_create_session_request(uint64_t imsi) // Check whether this UE is already registed std::map::iterator it = m_imsi_to_gtpc_ctx.find(imsi); if (it != m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->warning("Create Session Request being called for an UE with an active GTP-C connection.\n"); - m_mme_gtpc_log->warning("Deleting previous GTP-C connection.\n"); + m_logger.warning("Create Session Request being called for an UE with an active GTP-C connection."); + m_logger.warning("Deleting previous GTP-C connection."); std::map::iterator jt = m_mme_ctr_teid_to_imsi.find(it->second.mme_ctr_fteid.teid); if (jt == m_mme_ctr_teid_to_imsi.end()) { - m_mme_gtpc_log->error("Could not find IMSI from MME Ctrl TEID. MME Ctr TEID: %d\n", - it->second.mme_ctr_fteid.teid); + m_logger.error("Could not find IMSI from MME Ctrl TEID. MME Ctr TEID: %d", it->second.mme_ctr_fteid.teid); } else { m_mme_ctr_teid_to_imsi.erase(jt); } @@ -194,15 +190,15 @@ bool mme_gtpc::send_create_session_request(uint64_t imsi) bool mme_gtpc::handle_create_session_response(srslte::gtpc_pdu* cs_resp_pdu) { struct srslte::gtpc_create_session_response* cs_resp = &cs_resp_pdu->choice.create_session_response; - m_mme_gtpc_log->info("Received Create Session Response\n"); + m_logger.info("Received Create Session Response"); srslte::console("Received Create Session Response\n"); if (cs_resp_pdu->header.type != srslte::GTPC_MSG_TYPE_CREATE_SESSION_RESPONSE) { - m_mme_gtpc_log->warning("Could not create GTPC session. Not a create session response\n"); + m_logger.warning("Could not create GTPC session. Not a create session response"); // TODO Handle error return false; } if (cs_resp->cause.cause_value != srslte::GTPC_CAUSE_VALUE_REQUEST_ACCEPTED) { - m_mme_gtpc_log->warning("Could not create GTPC session. Create Session Request not accepted\n"); + m_logger.warning("Could not create GTPC session. Create Session Request not accepted"); // TODO Handle error return false; } @@ -210,12 +206,12 @@ bool mme_gtpc::handle_create_session_response(srslte::gtpc_pdu* cs_resp_pdu) // Get IMSI from the control TEID std::map::iterator id_it = m_mme_ctr_teid_to_imsi.find(cs_resp_pdu->header.teid); if (id_it == m_mme_ctr_teid_to_imsi.end()) { - m_mme_gtpc_log->warning("Could not find IMSI from Ctrl TEID.\n"); + m_logger.warning("Could not find IMSI from Ctrl TEID."); return false; } uint64_t imsi = id_it->second; - m_mme_gtpc_log->info("MME GTPC Ctrl TEID %" PRIu64 ", IMSI %" PRIu64 "\n", cs_resp_pdu->header.teid, imsi); + m_logger.info("MME GTPC Ctrl TEID %" PRIu64 ", IMSI %" PRIu64 "", cs_resp_pdu->header.teid, imsi); // Get S-GW Control F-TEID srslte::gtp_fteid_t sgw_ctr_fteid = {}; @@ -224,30 +220,30 @@ bool mme_gtpc::handle_create_session_response(srslte::gtpc_pdu* cs_resp_pdu) // Get S-GW S1-u F-TEID if (cs_resp->eps_bearer_context_created.s1_u_sgw_f_teid_present == false) { - m_mme_gtpc_log->error("Did not receive SGW S1-U F-TEID in create session response\n"); + m_logger.error("Did not receive SGW S1-U F-TEID in create session response"); return false; } srslte::console("Create Session Response -- SPGW control TEID %d\n", sgw_ctr_fteid.teid); - m_mme_gtpc_log->info("Create Session Response -- SPGW control TEID %d\n", sgw_ctr_fteid.teid); + m_logger.info("Create Session Response -- SPGW control TEID %d", sgw_ctr_fteid.teid); in_addr s1u_addr; s1u_addr.s_addr = cs_resp->eps_bearer_context_created.s1_u_sgw_f_teid.ipv4; srslte::console("Create Session Response -- SPGW S1-U Address: %s\n", inet_ntoa(s1u_addr)); - m_mme_gtpc_log->info("Create Session Response -- SPGW S1-U Address: %s\n", inet_ntoa(s1u_addr)); + m_logger.info("Create Session Response -- SPGW S1-U Address: %s", inet_ntoa(s1u_addr)); // Check UE Ipv4 address was allocated if (cs_resp->paa_present != true) { - m_mme_gtpc_log->error("PDN Adress Allocation not present\n"); + m_logger.error("PDN Adress Allocation not present"); return false; } if (cs_resp->paa.pdn_type != srslte::GTPC_PDN_TYPE_IPV4) { - m_mme_gtpc_log->error("IPv6 not supported yet\n"); + m_logger.error("IPv6 not supported yet"); return false; } // Save create session response info to E-RAB context nas* nas_ctx = m_s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { - m_mme_gtpc_log->error("Could not find UE context. IMSI %015" PRIu64 "\n", imsi); + m_logger.error("Could not find UE context. IMSI %015" PRIu64 "", imsi); return false; } emm_ctx_t* emm_ctx = &nas_ctx->m_emm_ctx; @@ -261,7 +257,7 @@ bool mme_gtpc::handle_create_session_response(srslte::gtpc_pdu* cs_resp_pdu) std::map::iterator it_g = m_imsi_to_gtpc_ctx.find(imsi); if (it_g == m_imsi_to_gtpc_ctx.end()) { // Could not find GTP-C Context - m_mme_gtpc_log->error("Could not find GTP-C context\n"); + m_logger.error("Could not find GTP-C context"); return false; } gtpc_ctx_t* gtpc_ctx = &it_g->second; @@ -279,13 +275,13 @@ bool mme_gtpc::handle_create_session_response(srslte::gtpc_pdu* cs_resp_pdu) bool mme_gtpc::send_modify_bearer_request(uint64_t imsi, uint16_t erab_to_modify, srslte::gtp_fteid_t* enb_fteid) { - m_mme_gtpc_log->info("Sending GTP-C Modify bearer request\n"); + m_logger.info("Sending GTP-C Modify bearer request"); srslte::gtpc_pdu mb_req_pdu; std::memset(&mb_req_pdu, 0, sizeof(mb_req_pdu)); std::map::iterator it = m_imsi_to_gtpc_ctx.find(imsi); if (it == m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->error("Modify bearer request for UE without GTP-C connection\n"); + m_logger.error("Modify bearer request for UE without GTP-C connection"); return false; } srslte::gtp_fteid_t sgw_ctr_fteid = it->second.sgw_ctr_fteid; @@ -300,10 +296,10 @@ bool mme_gtpc::send_modify_bearer_request(uint64_t imsi, uint16_t erab_to_modify mb_req->eps_bearer_context_to_modify.s1_u_enb_f_teid.ipv4 = enb_fteid->ipv4; mb_req->eps_bearer_context_to_modify.s1_u_enb_f_teid.teid = enb_fteid->teid; - m_mme_gtpc_log->info("GTP-C Modify bearer request -- S-GW Control TEID %d\n", sgw_ctr_fteid.teid); + m_logger.info("GTP-C Modify bearer request -- S-GW Control TEID %d", sgw_ctr_fteid.teid); struct in_addr addr; addr.s_addr = enb_fteid->ipv4; - m_mme_gtpc_log->info("GTP-C Modify bearer request -- S1-U TEID 0x%x, IP %s\n", enb_fteid->teid, inet_ntoa(addr)); + m_logger.info("GTP-C Modify bearer request -- S1-U TEID 0x%x, IP %s", enb_fteid->teid, inet_ntoa(addr)); // Send msg to SPGW send_s11_pdu(mb_req_pdu); @@ -315,12 +311,12 @@ void mme_gtpc::handle_modify_bearer_response(srslte::gtpc_pdu* mb_resp_pdu) uint32_t mme_ctrl_teid = mb_resp_pdu->header.teid; std::map::iterator imsi_it = m_mme_ctr_teid_to_imsi.find(mme_ctrl_teid); if (imsi_it == m_mme_ctr_teid_to_imsi.end()) { - m_mme_gtpc_log->error("Could not find IMSI from control TEID\n"); + m_logger.error("Could not find IMSI from control TEID"); return; } uint8_t ebi = mb_resp_pdu->choice.modify_bearer_response.eps_bearer_context_modified.ebi; - m_mme_gtpc_log->debug("Activating EPS bearer with id %d\n", ebi); + m_logger.debug("Activating EPS bearer with id %d", ebi); m_s1ap->activate_eps_bearer(imsi_it->second, ebi); return; @@ -328,7 +324,7 @@ void mme_gtpc::handle_modify_bearer_response(srslte::gtpc_pdu* mb_resp_pdu) bool mme_gtpc::send_delete_session_request(uint64_t imsi) { - m_mme_gtpc_log->info("Sending GTP-C Delete Session Request request. IMSI %" PRIu64 "\n", imsi); + m_logger.info("Sending GTP-C Delete Session Request request. IMSI %" PRIu64 "", imsi); srslte::gtpc_pdu del_req_pdu; std::memset(&del_req_pdu, 0, sizeof(del_req_pdu)); srslte::gtp_fteid_t sgw_ctr_fteid; @@ -337,7 +333,7 @@ bool mme_gtpc::send_delete_session_request(uint64_t imsi) // Get S-GW Ctr TEID std::map::iterator it_ctx = m_imsi_to_gtpc_ctx.find(imsi); if (it_ctx == m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->error("Could not find GTP-C context to remove\n"); + m_logger.error("Could not find GTP-C context to remove"); return false; } @@ -350,7 +346,7 @@ bool mme_gtpc::send_delete_session_request(uint64_t imsi) srslte::gtpc_delete_session_request* del_req = &del_req_pdu.choice.delete_session_request; del_req->cause.cause_value = srslte::GTPC_CAUSE_VALUE_ISR_DEACTIVATION; - m_mme_gtpc_log->info("GTP-C Delete Session Request -- S-GW Control TEID %d\n", sgw_ctr_fteid.teid); + m_logger.info("GTP-C Delete Session Request -- S-GW Control TEID %d", sgw_ctr_fteid.teid); // Send msg to SPGW send_s11_pdu(del_req_pdu); @@ -358,7 +354,7 @@ bool mme_gtpc::send_delete_session_request(uint64_t imsi) // Delete GTP-C context std::map::iterator it_imsi = m_mme_ctr_teid_to_imsi.find(mme_ctr_fteid.teid); if (it_imsi == m_mme_ctr_teid_to_imsi.end()) { - m_mme_gtpc_log->error("Could not find IMSI from MME ctr TEID"); + m_logger.error("Could not find IMSI from MME ctr TEID"); } else { m_mme_ctr_teid_to_imsi.erase(it_imsi); } @@ -369,7 +365,7 @@ bool mme_gtpc::send_delete_session_request(uint64_t imsi) void mme_gtpc::send_release_access_bearers_request(uint64_t imsi) { // The GTP-C connection will not be torn down, just the user plane bearers. - m_mme_gtpc_log->info("Sending GTP-C Release Access Bearers Request\n"); + m_logger.info("Sending GTP-C Release Access Bearers Request"); srslte::gtpc_pdu rel_req_pdu; std::memset(&rel_req_pdu, 0, sizeof(rel_req_pdu)); srslte::gtp_fteid_t sgw_ctr_fteid; @@ -377,7 +373,7 @@ void mme_gtpc::send_release_access_bearers_request(uint64_t imsi) // Get S-GW Ctr TEID std::map::iterator it_ctx = m_imsi_to_gtpc_ctx.find(imsi); if (it_ctx == m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->error("Could not find GTP-C context to remove\n"); + m_logger.error("Could not find GTP-C context to remove"); return; } sgw_ctr_fteid = it_ctx->second.sgw_ctr_fteid; @@ -389,7 +385,7 @@ void mme_gtpc::send_release_access_bearers_request(uint64_t imsi) header->type = srslte::GTPC_MSG_TYPE_RELEASE_ACCESS_BEARERS_REQUEST; srslte::gtpc_release_access_bearers_request* rel_req = &rel_req_pdu.choice.release_access_bearers_request; - m_mme_gtpc_log->info("GTP-C Release Access Berarers Request -- S-GW Control TEID %d\n", sgw_ctr_fteid.teid); + m_logger.info("GTP-C Release Access Berarers Request -- S-GW Control TEID %d", sgw_ctr_fteid.teid); // Send msg to SPGW send_s11_pdu(rel_req_pdu); @@ -403,16 +399,16 @@ bool mme_gtpc::handle_downlink_data_notification(srslte::gtpc_pdu* dl_not_pdu) srslte::gtpc_downlink_data_notification* dl_not = &dl_not_pdu->choice.downlink_data_notification; std::map::iterator imsi_it = m_mme_ctr_teid_to_imsi.find(mme_ctrl_teid); if (imsi_it == m_mme_ctr_teid_to_imsi.end()) { - m_mme_gtpc_log->error("Could not find IMSI from control TEID\n"); + m_logger.error("Could not find IMSI from control TEID"); return false; } if (!dl_not->eps_bearer_id_present) { - m_mme_gtpc_log->error("No EPS bearer Id in downlink data notification\n"); + m_logger.error("No EPS bearer Id in downlink data notification"); return false; } uint8_t ebi = dl_not->eps_bearer_id; - m_mme_gtpc_log->debug("Downlink Data Notification -- IMSI: %015" PRIu64 ", EBI %d\n", imsi_it->second, ebi); + m_logger.debug("Downlink Data Notification -- IMSI: %015" PRIu64 ", EBI %d", imsi_it->second, ebi); m_s1ap->send_paging(imsi_it->second, ebi); return true; @@ -420,7 +416,7 @@ bool mme_gtpc::handle_downlink_data_notification(srslte::gtpc_pdu* dl_not_pdu) void mme_gtpc::send_downlink_data_notification_acknowledge(uint64_t imsi, enum srslte::gtpc_cause_value cause) { - m_mme_gtpc_log->debug("Sending GTP-C Data Notification Acknowledge. Cause %d\n", cause); + m_logger.debug("Sending GTP-C Data Notification Acknowledge. Cause %d", cause); srslte::gtpc_pdu not_ack_pdu; srslte::gtp_fteid_t sgw_ctr_fteid; std::memset(¬_ack_pdu, 0, sizeof(not_ack_pdu)); @@ -428,7 +424,7 @@ void mme_gtpc::send_downlink_data_notification_acknowledge(uint64_t imsi, enum s // get s-gw ctr teid std::map::iterator it_ctx = m_imsi_to_gtpc_ctx.find(imsi); if (it_ctx == m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->error("could not find gtp-c context to remove\n"); + m_logger.error("could not find gtp-c context to remove"); return; } sgw_ctr_fteid = it_ctx->second.sgw_ctr_fteid; @@ -441,7 +437,7 @@ void mme_gtpc::send_downlink_data_notification_acknowledge(uint64_t imsi, enum s srslte::gtpc_downlink_data_notification_acknowledge* not_ack = ¬_ack_pdu.choice.downlink_data_notification_acknowledge; - m_mme_gtpc_log->info("gtp-c downlink data notification acknowledge -- s-gw control teid %d\n", sgw_ctr_fteid.teid); + m_logger.info("gtp-c downlink data notification acknowledge -- s-gw control teid %d", sgw_ctr_fteid.teid); // send msg to spgw send_s11_pdu(not_ack_pdu); @@ -450,7 +446,7 @@ void mme_gtpc::send_downlink_data_notification_acknowledge(uint64_t imsi, enum s bool mme_gtpc::send_downlink_data_notification_failure_indication(uint64_t imsi, enum srslte::gtpc_cause_value cause) { - m_mme_gtpc_log->debug("Sending GTP-C Data Notification Failure Indication. Cause %d\n", cause); + m_logger.debug("Sending GTP-C Data Notification Failure Indication. Cause %d", cause); srslte::gtpc_pdu not_fail_pdu; srslte::gtp_fteid_t sgw_ctr_fteid; std::memset(¬_fail_pdu, 0, sizeof(not_fail_pdu)); @@ -458,7 +454,7 @@ bool mme_gtpc::send_downlink_data_notification_failure_indication(uint64_t imsi, // get s-gw ctr teid std::map::iterator it_ctx = m_imsi_to_gtpc_ctx.find(imsi); if (it_ctx == m_imsi_to_gtpc_ctx.end()) { - m_mme_gtpc_log->error("could not find gtp-c context to send paging failure\n"); + m_logger.error("could not find gtp-c context to send paging failure"); return false; } sgw_ctr_fteid = it_ctx->second.sgw_ctr_fteid; @@ -472,7 +468,7 @@ bool mme_gtpc::send_downlink_data_notification_failure_indication(uint64_t imsi, srslte::gtpc_downlink_data_notification_failure_indication* not_fail = ¬_fail_pdu.choice.downlink_data_notification_failure_indication; not_fail->cause.cause_value = cause; - m_mme_gtpc_log->info("Downlink Data Notification Failure Indication -- SP-GW control teid %d\n", sgw_ctr_fteid.teid); + m_logger.info("Downlink Data Notification Failure Indication -- SP-GW control teid %d", sgw_ctr_fteid.teid); // send msg to spgw send_s11_pdu(not_fail_pdu); diff --git a/srsepc/src/mme/nas.cc b/srsepc/src/mme/nas.cc index 420cfe70f..f65d594bc 100644 --- a/srsepc/src/mme/nas.cc +++ b/srsepc/src/mme/nas.cc @@ -22,9 +22,8 @@ namespace srsepc { -nas::nas(const nas_init_t& args, const nas_if_t& itf, srslte::log* nas_log) : +nas::nas(const nas_init_t& args, const nas_if_t& itf) : m_pool(srslte::byte_buffer_pool::get_instance()), - m_nas_log(nas_log), m_gtpc(itf.gtpc), m_s1ap(itf.s1ap), m_hss(itf.hss), @@ -40,7 +39,7 @@ nas::nas(const nas_init_t& args, const nas_if_t& itf, srslte::log* nas_log) : { m_sec_ctx.integ_algo = args.integ_algo; m_sec_ctx.cipher_algo = args.cipher_algo; - m_nas_log->debug("NAS Context Initialized. MCC: 0x%x, MNC 0x%x\n", m_mcc, m_mnc); + m_logger.debug("NAS Context Initialized. MCC: 0x%x, MNC 0x%x", m_mcc, m_mnc); } void nas::reset() @@ -67,13 +66,13 @@ bool nas::handle_attach_request(uint32_t enb_ue_s1ap_id, struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { uint32_t m_tmsi = 0; uint64_t imsi = 0; LIBLTE_MME_ATTACH_REQUEST_MSG_STRUCT attach_req = {}; LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT pdn_con_req = {}; + auto& nas_logger = srslog::fetch_basic_logger("NAS"); // Interfaces s1ap_interface_nas* s1ap = itf.s1ap; @@ -83,13 +82,13 @@ bool nas::handle_attach_request(uint32_t enb_ue_s1ap_id, // Get NAS Attach Request and PDN connectivity request messages LIBLTE_ERROR_ENUM err = liblte_mme_unpack_attach_request_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &attach_req); if (err != LIBLTE_SUCCESS) { - nas_log->error("Error unpacking NAS attach request. Error: %s\n", liblte_error_text[err]); + nas_logger.error("Error unpacking NAS attach request. Error: %s", liblte_error_text[err]); return false; } // Get PDN Connectivity Request*/ err = liblte_mme_unpack_pdn_connectivity_request_msg(&attach_req.esm_msg, &pdn_con_req); if (err != LIBLTE_SUCCESS) { - nas_log->error("Error unpacking NAS PDN Connectivity Request. Error: %s\n", liblte_error_text[err]); + nas_logger.error("Error unpacking NAS PDN Connectivity Request. Error: %s", liblte_error_text[err]); return false; } @@ -99,22 +98,22 @@ bool nas::handle_attach_request(uint32_t enb_ue_s1ap_id, imsi += attach_req.eps_mobile_id.imsi[i] * std::pow(10, 14 - i); } srslte::console("Attach request -- IMSI: %015" PRIu64 "\n", imsi); - nas_log->info("Attach request -- IMSI: %015" PRIu64 "\n", imsi); + nas_logger.info("Attach request -- IMSI: %015" PRIu64 "", imsi); } else if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_GUTI) { m_tmsi = attach_req.eps_mobile_id.guti.m_tmsi; imsi = s1ap->find_imsi_from_m_tmsi(m_tmsi); srslte::console("Attach request -- M-TMSI: 0x%x\n", m_tmsi); - nas_log->info("Attach request -- M-TMSI: 0x%x\n", m_tmsi); + nas_logger.info("Attach request -- M-TMSI: 0x%x", m_tmsi); } else { - nas_log->error("Unhandled Mobile Id type in attach request\n"); + nas_logger.error("Unhandled Mobile Id type in attach request"); return false; } // Log Attach Request Information srslte::console("Attach request -- eNB-UE S1AP Id: %d\n", enb_ue_s1ap_id); - nas_log->info("Attach request -- eNB-UE S1AP Id: %d\n", enb_ue_s1ap_id); + nas_logger.info("Attach request -- eNB-UE S1AP Id: %d", enb_ue_s1ap_id); srslte::console("Attach request -- Attach type: %d\n", attach_req.eps_attach_type); - nas_log->info("Attach request -- Attach type: %d\n", attach_req.eps_attach_type); + nas_logger.info("Attach request -- Attach type: %d", attach_req.eps_attach_type); srslte::console("Attach Request -- UE Network Capabilities EEA: %d%d%d%d%d%d%d%d\n", attach_req.ue_network_cap.eea[0], attach_req.ue_network_cap.eea[1], @@ -124,15 +123,15 @@ bool nas::handle_attach_request(uint32_t enb_ue_s1ap_id, attach_req.ue_network_cap.eea[5], attach_req.ue_network_cap.eea[6], attach_req.ue_network_cap.eea[7]); - nas_log->info("Attach Request -- UE Network Capabilities EEA: %d%d%d%d%d%d%d%d\n", - attach_req.ue_network_cap.eea[0], - attach_req.ue_network_cap.eea[1], - attach_req.ue_network_cap.eea[2], - attach_req.ue_network_cap.eea[3], - attach_req.ue_network_cap.eea[4], - attach_req.ue_network_cap.eea[5], - attach_req.ue_network_cap.eea[6], - attach_req.ue_network_cap.eea[7]); + nas_logger.info("Attach Request -- UE Network Capabilities EEA: %d%d%d%d%d%d%d%d", + attach_req.ue_network_cap.eea[0], + attach_req.ue_network_cap.eea[1], + attach_req.ue_network_cap.eea[2], + attach_req.ue_network_cap.eea[3], + attach_req.ue_network_cap.eea[4], + attach_req.ue_network_cap.eea[5], + attach_req.ue_network_cap.eea[6], + attach_req.ue_network_cap.eea[7]); srslte::console("Attach Request -- UE Network Capabilities EIA: %d%d%d%d%d%d%d%d\n", attach_req.ue_network_cap.eia[0], attach_req.ue_network_cap.eia[1], @@ -142,48 +141,48 @@ bool nas::handle_attach_request(uint32_t enb_ue_s1ap_id, attach_req.ue_network_cap.eia[5], attach_req.ue_network_cap.eia[6], attach_req.ue_network_cap.eia[7]); - nas_log->info("Attach Request -- UE Network Capabilities EIA: %d%d%d%d%d%d%d%d\n", - attach_req.ue_network_cap.eia[0], - attach_req.ue_network_cap.eia[1], - attach_req.ue_network_cap.eia[2], - attach_req.ue_network_cap.eia[3], - attach_req.ue_network_cap.eia[4], - attach_req.ue_network_cap.eia[5], - attach_req.ue_network_cap.eia[6], - attach_req.ue_network_cap.eia[7]); + nas_logger.info("Attach Request -- UE Network Capabilities EIA: %d%d%d%d%d%d%d%d", + attach_req.ue_network_cap.eia[0], + attach_req.ue_network_cap.eia[1], + attach_req.ue_network_cap.eia[2], + attach_req.ue_network_cap.eia[3], + attach_req.ue_network_cap.eia[4], + attach_req.ue_network_cap.eia[5], + attach_req.ue_network_cap.eia[6], + attach_req.ue_network_cap.eia[7]); srslte::console("Attach Request -- MS Network Capabilities Present: %s\n", attach_req.ms_network_cap_present ? "true" : "false"); - nas_log->info("Attach Request -- MS Network Capabilities Present: %s\n", - attach_req.ms_network_cap_present ? "true" : "false"); + nas_logger.info("Attach Request -- MS Network Capabilities Present: %s", + attach_req.ms_network_cap_present ? "true" : "false"); srslte::console("PDN Connectivity Request -- EPS Bearer Identity requested: %d\n", pdn_con_req.eps_bearer_id); - nas_log->info("PDN Connectivity Request -- EPS Bearer Identity requested: %d\n", pdn_con_req.eps_bearer_id); + nas_logger.info("PDN Connectivity Request -- EPS Bearer Identity requested: %d", pdn_con_req.eps_bearer_id); srslte::console("PDN Connectivity Request -- Procedure Transaction Id: %d\n", pdn_con_req.proc_transaction_id); - nas_log->info("PDN Connectivity Request -- Procedure Transaction Id: %d\n", pdn_con_req.proc_transaction_id); + nas_logger.info("PDN Connectivity Request -- Procedure Transaction Id: %d", pdn_con_req.proc_transaction_id); srslte::console("PDN Connectivity Request -- ESM Information Transfer requested: %s\n", pdn_con_req.esm_info_transfer_flag_present ? "true" : "false"); - nas_log->info("PDN Connectivity Request -- ESM Information Transfer requested: %s\n", - pdn_con_req.esm_info_transfer_flag_present ? "true" : "false"); + nas_logger.info("PDN Connectivity Request -- ESM Information Transfer requested: %s", + pdn_con_req.esm_info_transfer_flag_present ? "true" : "false"); // Get NAS Context if UE is known nas* nas_ctx = s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { // Get attach type from attach request if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_IMSI) { - nas::handle_imsi_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf, nas_log); + nas::handle_imsi_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf); } else if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_GUTI) { - nas::handle_guti_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf, nas_log); + nas::handle_guti_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf); } else { return false; } } else { - nas_log->info("Attach Request -- Found previously attached UE.\n"); + nas_logger.info("Attach Request -- Found previously attached UE."); srslte::console("Attach Request -- Found previously attach UE.\n"); if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_IMSI) { nas::handle_imsi_attach_request_known_ue( - nas_ctx, enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, nas_rx, args, itf, nas_log); + nas_ctx, enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, nas_rx, args, itf); } else if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_GUTI) { nas::handle_guti_attach_request_known_ue( - nas_ctx, enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, nas_rx, args, itf, nas_log); + nas_ctx, enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, nas_rx, args, itf); } else { return false; } @@ -196,12 +195,12 @@ bool nas::handle_imsi_attach_request_unknown_ue(uint32_t const LIBLTE_MME_ATTACH_REQUEST_MSG_STRUCT& attach_req, const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { nas* nas_ctx; srslte::byte_buffer_t* nas_tx; - srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); + srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); + auto& nas_logger = srslog::fetch_basic_logger("NAS"); // Interfaces s1ap_interface_nas* s1ap = itf.s1ap; @@ -215,7 +214,7 @@ bool nas::handle_imsi_attach_request_unknown_ue(uint32_t } // Create UE context - nas_ctx = new nas(args, itf, nas_log); + nas_ctx = new nas(args, itf); // Save IMSI, eNB UE S1AP Id, MME UE S1AP Id and make sure UE is EMM_DEREGISTERED nas_ctx->m_emm_ctx.imsi = imsi; @@ -262,7 +261,7 @@ bool nas::handle_imsi_attach_request_unknown_ue(uint32_t nas_ctx->m_sec_ctx.rand, nas_ctx->m_sec_ctx.xres)) { srslte::console("User not found. IMSI %015" PRIu64 "\n", nas_ctx->m_emm_ctx.imsi); - nas_log->info("User not found. IMSI %015" PRIu64 "\n", nas_ctx->m_emm_ctx.imsi); + nas_logger.info("User not found. IMSI %015" PRIu64 "", nas_ctx->m_emm_ctx.imsi); delete nas_ctx; return false; } @@ -285,7 +284,7 @@ bool nas::handle_imsi_attach_request_unknown_ue(uint32_t nas_ctx->m_ecm_ctx.enb_ue_s1ap_id, nas_ctx->m_ecm_ctx.mme_ue_s1ap_id, nas_tx, nas_ctx->m_ecm_ctx.enb_sri); pool->deallocate(nas_tx); - nas_log->info("Downlink NAS: Sending Authentication Request\n"); + nas_logger.info("Downlink NAS: Sending Authentication Request"); srslte::console("Downlink NAS: Sending Authentication Request\n"); return true; } @@ -297,10 +296,10 @@ bool nas::handle_imsi_attach_request_known_ue(nas* const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { - bool err; + bool err; + auto& nas_logger = srslog::fetch_basic_logger("NAS"); // Interfaces s1ap_interface_nas* s1ap = itf.s1ap; @@ -318,8 +317,7 @@ bool nas::handle_imsi_attach_request_known_ue(nas* s1ap->delete_ue_ctx(nas_ctx->m_emm_ctx.imsi); // Handle new attach - err = - nas::handle_imsi_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf, nas_log); + err = nas::handle_imsi_attach_request_unknown_ue(enb_ue_s1ap_id, enb_sri, attach_req, pdn_con_req, args, itf); return err; } @@ -328,8 +326,7 @@ bool nas::handle_guti_attach_request_unknown_ue(uint32_t const LIBLTE_MME_ATTACH_REQUEST_MSG_STRUCT& attach_req, const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { nas* nas_ctx; @@ -342,7 +339,7 @@ bool nas::handle_guti_attach_request_unknown_ue(uint32_t gtpc_interface_nas* gtpc = itf.gtpc; // Create new NAS context. - nas_ctx = new nas(args, itf, nas_log); + nas_ctx = new nas(args, itf); // Could not find IMSI from M-TMSI, send Id request // The IMSI will be set when the identity response is received @@ -406,12 +403,12 @@ bool nas::handle_guti_attach_request_known_ue(nas* const LIBLTE_MME_PDN_CONNECTIVITY_REQUEST_MSG_STRUCT& pdn_con_req, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { bool msg_valid = false; srslte::byte_buffer_t* nas_tx; - srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); + srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); + auto& nas_logger = srslog::fetch_basic_logger("NAS"); emm_ctx_t* emm_ctx = &nas_ctx->m_emm_ctx; ecm_ctx_t* ecm_ctx = &nas_ctx->m_ecm_ctx; @@ -432,8 +429,8 @@ bool nas::handle_guti_attach_request_known_ue(nas* if (msg_valid == true && emm_ctx->state == EMM_STATE_DEREGISTERED) { srslte::console( "GUTI Attach -- NAS Integrity OK. UL count %d, DL count %d\n", sec_ctx->ul_nas_count, sec_ctx->dl_nas_count); - nas_log->info( - "GUTI Attach -- NAS Integrity OK. UL count %d, DL count %d\n", sec_ctx->ul_nas_count, sec_ctx->dl_nas_count); + nas_logger.info( + "GUTI Attach -- NAS Integrity OK. UL count %d, DL count %d", sec_ctx->ul_nas_count, sec_ctx->dl_nas_count); // Create new MME UE S1AP Identity ecm_ctx->mme_ue_s1ap_id = s1ap->get_next_mme_ue_s1ap_id(); @@ -463,22 +460,22 @@ bool nas::handle_guti_attach_request_known_ue(nas* // Re-generate K_eNB srslte::security_generate_k_enb(sec_ctx->k_asme, sec_ctx->ul_nas_count, sec_ctx->k_enb); - nas_log->info("Generating KeNB with UL NAS COUNT: %d\n", sec_ctx->ul_nas_count); + nas_logger.info("Generating KeNB with UL NAS COUNT: %d", sec_ctx->ul_nas_count); srslte::console("Generating KeNB with UL NAS COUNT: %d\n", sec_ctx->ul_nas_count); - nas_log->info_hex(sec_ctx->k_enb, 32, "Key eNodeB (k_enb)\n"); + nas_logger.info(sec_ctx->k_enb, 32, "Key eNodeB (k_enb)"); // Send reply nas_tx = pool->allocate(); if (ecm_ctx->eit) { srslte::console("Secure ESM information transfer requested.\n"); - nas_log->info("Secure ESM information transfer requested.\n"); + nas_logger.info("Secure ESM information transfer requested."); nas_ctx->pack_esm_information_request(nas_tx); s1ap->send_downlink_nas_transport(ecm_ctx->enb_ue_s1ap_id, ecm_ctx->mme_ue_s1ap_id, nas_tx, *enb_sri); } else { // Get subscriber info from HSS uint8_t default_bearer = 5; hss->gen_update_loc_answer(emm_ctx->imsi, &nas_ctx->m_esm_ctx[default_bearer].qci); - nas_log->debug("Getting subscription information -- QCI %d\n", nas_ctx->m_esm_ctx[default_bearer].qci); + nas_logger.debug("Getting subscription information -- QCI %d", nas_ctx->m_esm_ctx[default_bearer].qci); srslte::console("Getting subscription information -- QCI %d\n", nas_ctx->m_esm_ctx[default_bearer].qci); gtpc->send_create_session_request(emm_ctx->imsi); } @@ -487,7 +484,7 @@ bool nas::handle_guti_attach_request_known_ue(nas* return true; } else { if (emm_ctx->state != EMM_STATE_DEREGISTERED) { - nas_log->error("Received GUTI-Attach Request from attached user.\n"); + nas_logger.error("Received GUTI-Attach Request from attached user."); srslte::console("Received GUTI-Attach Request from attached user.\n"); // Delete previous Ctx, restart authentication @@ -536,7 +533,7 @@ bool nas::handle_guti_attach_request_known_ue(nas* // Get Authentication Vectors from HSS if (!hss->gen_auth_info_answer(emm_ctx->imsi, sec_ctx->k_asme, sec_ctx->autn, sec_ctx->rand, sec_ctx->xres)) { srslte::console("User not found. IMSI %015" PRIu64 "\n", emm_ctx->imsi); - nas_log->info("User not found. IMSI %015" PRIu64 "\n", emm_ctx->imsi); + nas_logger.info("User not found. IMSI %015" PRIu64 "", emm_ctx->imsi); return false; } @@ -548,7 +545,7 @@ bool nas::handle_guti_attach_request_known_ue(nas* // Send reply to eNB s1ap->send_downlink_nas_transport(ecm_ctx->enb_ue_s1ap_id, ecm_ctx->mme_ue_s1ap_id, nas_tx, *enb_sri); pool->deallocate(nas_tx); - nas_log->info("Downlink NAS: Sent Authentication Request\n"); + nas_logger.info("Downlink NAS: Sent Authentication Request"); srslte::console("Downlink NAS: Sent Authentication Request\n"); return true; } @@ -560,12 +557,13 @@ bool nas::handle_service_request(uint32_t m_tmsi, struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { - nas_log->info("Service request -- S-TMSI 0x%x\n", m_tmsi); + auto& nas_logger = srslog::fetch_basic_logger("NAS"); + + nas_logger.info("Service request -- S-TMSI 0x%x", m_tmsi); srslte::console("Service request -- S-TMSI 0x%x\n", m_tmsi); - nas_log->info("Service request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); + nas_logger.info("Service request -- eNB UE S1AP Id %d", enb_ue_s1ap_id); srslte::console("Service request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); bool mac_valid = false; @@ -580,15 +578,15 @@ bool nas::handle_service_request(uint32_t m_tmsi, LIBLTE_ERROR_ENUM err = liblte_mme_unpack_service_request_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &service_req); if (err != LIBLTE_SUCCESS) { - nas_log->error("Could not unpack service request\n"); + nas_logger.error("Could not unpack service request"); return false; } uint64_t imsi = s1ap->find_imsi_from_m_tmsi(m_tmsi); if (imsi == 0) { srslte::console("Could not find IMSI from M-TMSI. M-TMSI 0x%x\n", m_tmsi); - nas_log->error("Could not find IMSI from M-TMSI. M-TMSI 0x%x\n", m_tmsi); - nas nas_tmp(args, itf, nas_log); + nas_logger.error("Could not find IMSI from M-TMSI. M-TMSI 0x%x", m_tmsi); + nas nas_tmp(args, itf); nas_tmp.m_ecm_ctx.enb_ue_s1ap_id = enb_ue_s1ap_id; nas_tmp.m_ecm_ctx.mme_ue_s1ap_id = s1ap->get_next_mme_ue_s1ap_id(); @@ -602,8 +600,8 @@ bool nas::handle_service_request(uint32_t m_tmsi, nas* nas_ctx = s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL || nas_ctx->m_emm_ctx.state != EMM_STATE_REGISTERED) { srslte::console("UE is not EMM-Registered.\n"); - nas_log->error("UE is not EMM-Registered.\n"); - nas nas_tmp(args, itf, nas_log); + nas_logger.error("UE is not EMM-Registered."); + nas nas_tmp(args, itf); nas_tmp.m_ecm_ctx.enb_ue_s1ap_id = enb_ue_s1ap_id; nas_tmp.m_ecm_ctx.mme_ue_s1ap_id = s1ap->get_next_mme_ue_s1ap_id(); @@ -620,14 +618,14 @@ bool nas::handle_service_request(uint32_t m_tmsi, mac_valid = nas_ctx->short_integrity_check(nas_rx); if (mac_valid) { srslte::console("Service Request -- Short MAC valid\n"); - nas_log->info("Service Request -- Short MAC valid\n"); + nas_logger.info("Service Request -- Short MAC valid"); if (ecm_ctx->state == ECM_STATE_CONNECTED) { - nas_log->error("Service Request -- User is ECM CONNECTED\n"); + nas_logger.error("Service Request -- User is ECM CONNECTED"); // Release previous context - nas_log->info("Service Request -- Releasing previouse ECM context. eNB S1AP Id %d, MME UE S1AP Id %d\n", - ecm_ctx->enb_ue_s1ap_id, - ecm_ctx->mme_ue_s1ap_id); + nas_logger.info("Service Request -- Releasing previouse ECM context. eNB S1AP Id %d, MME UE S1AP Id %d", + ecm_ctx->enb_ue_s1ap_id, + ecm_ctx->mme_ue_s1ap_id); s1ap->send_ue_context_release_command(ecm_ctx->mme_ue_s1ap_id); s1ap->release_ue_ecm_ctx(ecm_ctx->mme_ue_s1ap_id); } @@ -636,7 +634,7 @@ bool nas::handle_service_request(uint32_t m_tmsi, // UE not connect. Connect normally. srslte::console("Service Request -- User is ECM DISCONNECTED\n"); - nas_log->info("Service Request -- User is ECM DISCONNECTED\n"); + nas_logger.info("Service Request -- User is ECM DISCONNECTED"); // Create ECM context ecm_ctx->mme_ue_s1ap_id = s1ap->get_next_mme_ue_s1ap_id(); @@ -650,16 +648,16 @@ bool nas::handle_service_request(uint32_t m_tmsi, // Get UE IP, and uplink F-TEID if (emm_ctx->ue_ip.s_addr == 0) { - nas_log->error("UE has no valid IP assigned upon reception of service request"); + nas_logger.error("UE has no valid IP assigned upon reception of service request"); } srslte::console("UE previously assigned IP: %s\n", inet_ntoa(emm_ctx->ue_ip)); // Re-generate K_eNB srslte::security_generate_k_enb(sec_ctx->k_asme, sec_ctx->ul_nas_count, sec_ctx->k_enb); - nas_log->info("Generating KeNB with UL NAS COUNT: %d\n", sec_ctx->ul_nas_count); + nas_logger.info("Generating KeNB with UL NAS COUNT: %d", sec_ctx->ul_nas_count); srslte::console("Generating KeNB with UL NAS COUNT: %d\n", sec_ctx->ul_nas_count); - nas_log->info_hex(sec_ctx->k_enb, 32, "Key eNodeB (k_enb)\n"); + nas_logger.info(sec_ctx->k_enb, 32, "Key eNodeB (k_enb)"); srslte::console("UE Ctr TEID %d\n", emm_ctx->sgw_ctrl_fteid.teid); // Stop T3413 if running @@ -673,14 +671,14 @@ bool nas::handle_service_request(uint32_t m_tmsi, sec_ctx->ul_nas_count++; } else { srslte::console("Service Request -- Short MAC invalid\n"); - nas_log->info("Service Request -- Short MAC invalid\n"); + nas_logger.info("Service Request -- Short MAC invalid"); if (ecm_ctx->state == ECM_STATE_CONNECTED) { - nas_log->error("Service Request -- User is ECM CONNECTED\n"); + nas_logger.error("Service Request -- User is ECM CONNECTED"); // Release previous context - nas_log->info("Service Request -- Releasing previouse ECM context. eNB S1AP Id %d, MME UE S1AP Id %d\n", - ecm_ctx->enb_ue_s1ap_id, - ecm_ctx->mme_ue_s1ap_id); + nas_logger.info("Service Request -- Releasing previouse ECM context. eNB S1AP Id %d, MME UE S1AP Id %d", + ecm_ctx->enb_ue_s1ap_id, + ecm_ctx->mme_ue_s1ap_id); s1ap->send_ue_context_release_command(ecm_ctx->mme_ue_s1ap_id); s1ap->release_ue_ecm_ctx(ecm_ctx->mme_ue_s1ap_id); } @@ -698,8 +696,8 @@ bool nas::handle_service_request(uint32_t m_tmsi, pool->deallocate(nas_tx); srslte::console("Service Request -- Short MAC invalid. Sending service reject.\n"); - nas_log->warning("Service Request -- Short MAC invalid. Sending service reject.\n"); - nas_log->info("Service Reject -- eNB_UE_S1AP_ID %d MME_UE_S1AP_ID %d.\n", enb_ue_s1ap_id, ecm_ctx->mme_ue_s1ap_id); + nas_logger.warning("Service Request -- Short MAC invalid. Sending service reject."); + nas_logger.info("Service Reject -- eNB_UE_S1AP_ID %d MME_UE_S1AP_ID %d.", enb_ue_s1ap_id, ecm_ctx->mme_ue_s1ap_id); } return true; } @@ -709,12 +707,13 @@ bool nas::handle_detach_request(uint32_t m_tmsi, struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { - nas_log->info("Detach Request -- S-TMSI 0x%x\n", m_tmsi); + auto& nas_logger = srslog::fetch_basic_logger("NAS"); + + nas_logger.info("Detach Request -- S-TMSI 0x%x", m_tmsi); srslte::console("Detach Request -- S-TMSI 0x%x\n", m_tmsi); - nas_log->info("Detach Request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); + nas_logger.info("Detach Request -- eNB UE S1AP Id %d", enb_ue_s1ap_id); srslte::console("Detach Request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); bool mac_valid = false; @@ -727,21 +726,21 @@ bool nas::handle_detach_request(uint32_t m_tmsi, LIBLTE_ERROR_ENUM err = liblte_mme_unpack_detach_request_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &detach_req); if (err != LIBLTE_SUCCESS) { - nas_log->error("Could not unpack detach request\n"); + nas_logger.error("Could not unpack detach request"); return false; } uint64_t imsi = s1ap->find_imsi_from_m_tmsi(m_tmsi); if (imsi == 0) { srslte::console("Could not find IMSI from M-TMSI. M-TMSI 0x%x\n", m_tmsi); - nas_log->error("Could not find IMSI from M-TMSI. M-TMSI 0x%x\n", m_tmsi); + nas_logger.error("Could not find IMSI from M-TMSI. M-TMSI 0x%x", m_tmsi); return true; } nas* nas_ctx = s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { srslte::console("Could not find UE context from IMSI\n"); - nas_log->error("Could not find UE context from IMSI\n"); + nas_logger.error("Could not find UE context from IMSI"); return true; } @@ -772,18 +771,18 @@ bool nas::handle_tracking_area_update_request(uint32_t m_tmsi, struct sctp_sndrcvinfo* enb_sri, srslte::byte_buffer_t* nas_rx, const nas_init_t& args, - const nas_if_t& itf, - srslte::log* nas_log) + const nas_if_t& itf) { - srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); + auto& nas_logger = srslog::fetch_basic_logger("NAS"); + srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); - nas_log->info("Tracking Area Update Request -- S-TMSI 0x%x\n", m_tmsi); + nas_logger.info("Tracking Area Update Request -- S-TMSI 0x%x", m_tmsi); srslte::console("Tracking Area Update Request -- S-TMSI 0x%x\n", m_tmsi); - nas_log->info("Tracking Area Update Request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); + nas_logger.info("Tracking Area Update Request -- eNB UE S1AP Id %d", enb_ue_s1ap_id); srslte::console("Tracking Area Update Request -- eNB UE S1AP Id %d\n", enb_ue_s1ap_id); srslte::console("Warning: Tracking area update requests are not handled yet.\n"); - nas_log->warning("Tracking area update requests are not handled yet.\n"); + nas_logger.warning("Tracking area update requests are not handled yet."); // Interfaces s1ap_interface_nas* s1ap = itf.s1ap; @@ -793,7 +792,7 @@ bool nas::handle_tracking_area_update_request(uint32_t m_tmsi, // TODO don't search for NAS ctxt, just send that reject // with context we could enable integrity protection - nas nas_tmp(args, itf, nas_log); + nas nas_tmp(args, itf); nas_tmp.m_ecm_ctx.enb_ue_s1ap_id = enb_ue_s1ap_id; nas_tmp.m_ecm_ctx.mme_ue_s1ap_id = s1ap->get_next_mme_ue_s1ap_id(); @@ -819,13 +818,13 @@ bool nas::handle_attach_request(srslte::byte_buffer_t* nas_rx) // Get NAS Attach Request and PDN connectivity request messages LIBLTE_ERROR_ENUM err = liblte_mme_unpack_attach_request_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &attach_req); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS attach request. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS attach request. Error: %s", liblte_error_text[err]); return false; } // Get PDN Connectivity Request*/ err = liblte_mme_unpack_pdn_connectivity_request_msg(&attach_req.esm_msg, &pdn_con_req); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS PDN Connectivity Request. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS PDN Connectivity Request. Error: %s", liblte_error_text[err]); return false; } @@ -835,20 +834,20 @@ bool nas::handle_attach_request(srslte::byte_buffer_t* nas_rx) imsi += attach_req.eps_mobile_id.imsi[i] * std::pow(10, 14 - i); } srslte::console("Attach request -- IMSI: %015" PRIu64 "\n", imsi); - m_nas_log->info("Attach request -- IMSI: %015" PRIu64 "\n", imsi); + m_logger.info("Attach request -- IMSI: %015" PRIu64 "", imsi); } else if (attach_req.eps_mobile_id.type_of_id == LIBLTE_MME_EPS_MOBILE_ID_TYPE_GUTI) { m_tmsi = attach_req.eps_mobile_id.guti.m_tmsi; imsi = m_s1ap->find_imsi_from_m_tmsi(m_tmsi); srslte::console("Attach request -- M-TMSI: 0x%x\n", m_tmsi); - m_nas_log->info("Attach request -- M-TMSI: 0x%x\n", m_tmsi); + m_logger.info("Attach request -- M-TMSI: 0x%x", m_tmsi); } else { - m_nas_log->error("Unhandled Mobile Id type in attach request\n"); + m_logger.error("Unhandled Mobile Id type in attach request"); return false; } // Is UE known? if (m_emm_ctx.imsi == 0) { - m_nas_log->info("Attach request from Unkonwn UE\n"); + m_logger.info("Attach request from Unkonwn UE"); // Get IMSI uint64_t imsi = 0; for (int i = 0; i <= 14; i++) { @@ -889,7 +888,7 @@ bool nas::handle_attach_request(srslte::byte_buffer_t* nas_rx) if (!m_hss->gen_auth_info_answer( m_emm_ctx.imsi, m_sec_ctx.k_asme, m_sec_ctx.autn, m_sec_ctx.rand, m_sec_ctx.xres)) { srslte::console("User not found. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info("User not found. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); + m_logger.info("User not found. IMSI %015" PRIu64 "", m_emm_ctx.imsi); return false; } @@ -908,11 +907,11 @@ bool nas::handle_attach_request(srslte::byte_buffer_t* nas_rx) m_s1ap->send_downlink_nas_transport(m_ecm_ctx.enb_ue_s1ap_id, m_ecm_ctx.mme_ue_s1ap_id, nas_tx, m_ecm_ctx.enb_sri); m_pool->deallocate(nas_tx); - m_nas_log->info("Downlink NAS: Sending Authentication Request\n"); + m_logger.info("Downlink NAS: Sending Authentication Request"); srslte::console("Downlink NAS: Sending Authentication Request\n"); return true; } else { - m_nas_log->error("Attach request from known UE\n"); + m_logger.error("Attach request from known UE"); } return true; } @@ -926,15 +925,15 @@ bool nas::handle_authentication_response(srslte::byte_buffer_t* nas_rx) // Get NAS authentication response LIBLTE_ERROR_ENUM err = liblte_mme_unpack_authentication_response_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &auth_resp); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS authentication response. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS authentication response. Error: %s", liblte_error_text[err]); return false; } // Log received authentication response srslte::console("Authentication Response -- IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info("Authentication Response -- IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info_hex(auth_resp.res, 8, "Authentication response -- RES"); - m_nas_log->info_hex(m_sec_ctx.xres, 8, "Authentication response -- XRES"); + m_logger.info("Authentication Response -- IMSI %015" PRIu64 "", m_emm_ctx.imsi); + m_logger.info(auth_resp.res, 8, "Authentication response -- RES"); + m_logger.info(m_sec_ctx.xres, 8, "Authentication response -- XRES"); // Check UE authentication for (int i = 0; i < 8; i++) { @@ -947,15 +946,15 @@ bool nas::handle_authentication_response(srslte::byte_buffer_t* nas_rx) if (!ue_valid) { // Authentication rejected srslte::console("UE Authentication Rejected.\n"); - m_nas_log->warning("UE Authentication Rejected.\n"); + m_logger.warning("UE Authentication Rejected."); // Send back Athentication Reject pack_authentication_reject(nas_tx); - m_nas_log->info("Downlink NAS: Sending Authentication Reject.\n"); + m_logger.info("Downlink NAS: Sending Authentication Reject."); } else { // Authentication accepted srslte::console("UE Authentication Accepted.\n"); - m_nas_log->info("UE Authentication Accepted.\n"); + m_logger.info("UE Authentication Accepted."); // Send Security Mode Command m_sec_ctx.ul_nas_count = 0; // Reset the NAS uplink counter for the right key k_enb derivation @@ -977,12 +976,12 @@ bool nas::handle_security_mode_complete(srslte::byte_buffer_t* nas_rx) // Get NAS security mode complete LIBLTE_ERROR_ENUM err = liblte_mme_unpack_security_mode_complete_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &sm_comp); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS authentication response. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS authentication response. Error: %s", liblte_error_text[err]); return false; } // Log security mode complete - m_nas_log->info("Security Mode Command Complete -- IMSI: %015" PRIu64 "\n", m_emm_ctx.imsi); + m_logger.info("Security Mode Command Complete -- IMSI: %015" PRIu64 "", m_emm_ctx.imsi); srslte::console("Security Mode Command Complete -- IMSI: %015" PRIu64 "\n", m_emm_ctx.imsi); // Check wether secure ESM information transfer is required @@ -990,7 +989,7 @@ bool nas::handle_security_mode_complete(srslte::byte_buffer_t* nas_rx) if (m_ecm_ctx.eit == true) { // Secure ESM information transfer is required srslte::console("Sending ESM information request\n"); - m_nas_log->info("Sending ESM information request\n"); + m_logger.info("Sending ESM information request"); // Packing ESM information request pack_esm_information_request(nas_tx); @@ -1000,7 +999,7 @@ bool nas::handle_security_mode_complete(srslte::byte_buffer_t* nas_rx) // Sending create session request to SP-GW. uint8_t default_bearer = 5; m_hss->gen_update_loc_answer(m_emm_ctx.imsi, &m_esm_ctx[default_bearer].qci); - m_nas_log->debug("Getting subscription information -- QCI %d\n", m_esm_ctx[default_bearer].qci); + m_logger.debug("Getting subscription information -- QCI %d", m_esm_ctx[default_bearer].qci); srslte::console("Getting subscription information -- QCI %d\n", m_esm_ctx[default_bearer].qci); m_gtpc->send_create_session_request(m_emm_ctx.imsi); } @@ -1019,14 +1018,14 @@ bool nas::handle_attach_complete(srslte::byte_buffer_t* nas_rx) std::memset(&attach_comp, 0, sizeof(attach_comp)); LIBLTE_ERROR_ENUM err = liblte_mme_unpack_attach_complete_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &attach_comp); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS authentication response. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS authentication response. Error: %s", liblte_error_text[err]); return false; } err = liblte_mme_unpack_activate_default_eps_bearer_context_accept_msg((LIBLTE_BYTE_MSG_STRUCT*)&attach_comp.esm_msg, &act_bearer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking Activate EPS Bearer Context Accept Msg. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking Activate EPS Bearer Context Accept Msg. Error: %s", liblte_error_text[err]); return false; } @@ -1034,7 +1033,7 @@ bool nas::handle_attach_complete(srslte::byte_buffer_t* nas_rx) srslte::console("Unpacked Activate Default EPS Bearer message. EPS Bearer id %d\n", act_bearer.eps_bearer_id); if (act_bearer.eps_bearer_id < 5 || act_bearer.eps_bearer_id > 15) { - m_nas_log->error("EPS Bearer ID out of range\n"); + m_logger.error("EPS Bearer ID out of range"); return false; } if (m_emm_ctx.state == EMM_STATE_DEREGISTERED) { @@ -1050,7 +1049,7 @@ bool nas::handle_attach_complete(srslte::byte_buffer_t* nas_rx) m_pool->deallocate(nas_tx); srslte::console("Sending EMM Information\n"); - m_nas_log->info("Sending EMM Information\n"); + m_logger.info("Sending EMM Information"); } m_emm_ctx.state = EMM_STATE_REGISTERED; return true; @@ -1064,24 +1063,24 @@ bool nas::handle_esm_information_response(srslte::byte_buffer_t* nas_rx) LIBLTE_ERROR_ENUM err = srslte_mme_unpack_esm_information_response_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &esm_info_resp); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS authentication response. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS authentication response. Error: %s", liblte_error_text[err]); return false; } - m_nas_log->info("ESM Info: EPS bearer id %d\n", esm_info_resp.eps_bearer_id); + m_logger.info("ESM Info: EPS bearer id %d", esm_info_resp.eps_bearer_id); if (esm_info_resp.apn_present) { - m_nas_log->info("ESM Info: APN %s\n", esm_info_resp.apn.apn); + m_logger.info("ESM Info: APN %s", esm_info_resp.apn.apn); srslte::console("ESM Info: APN %s\n", esm_info_resp.apn.apn); } if (esm_info_resp.protocol_cnfg_opts_present) { - m_nas_log->info("ESM Info: %d Protocol Configuration Options\n", esm_info_resp.protocol_cnfg_opts.N_opts); + m_logger.info("ESM Info: %d Protocol Configuration Options", esm_info_resp.protocol_cnfg_opts.N_opts); srslte::console("ESM Info: %d Protocol Configuration Options\n", esm_info_resp.protocol_cnfg_opts.N_opts); } // Get subscriber info from HSS uint8_t default_bearer = 5; m_hss->gen_update_loc_answer(m_emm_ctx.imsi, &m_esm_ctx[default_bearer].qci); - m_nas_log->debug("Getting subscription information -- QCI %d\n", m_esm_ctx[default_bearer].qci); + m_logger.debug("Getting subscription information -- QCI %d", m_esm_ctx[default_bearer].qci); srslte::console("Getting subscription information -- QCI %d\n", m_esm_ctx[default_bearer].qci); // TODO The packging of GTP-C messages is not ready. @@ -1097,7 +1096,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) LIBLTE_ERROR_ENUM err = liblte_mme_unpack_identity_response_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &id_resp); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS identity response. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS identity response. Error: %s", liblte_error_text[err]); return false; } @@ -1106,7 +1105,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) imsi += id_resp.mobile_id.imsi[i] * std::pow(10, 14 - i); } - m_nas_log->info("ID response -- IMSI: %015" PRIu64 "\n", imsi); + m_logger.info("ID response -- IMSI: %015" PRIu64 "", imsi); srslte::console("ID Response -- IMSI: %015" PRIu64 "\n", imsi); // Set UE's IMSI @@ -1115,7 +1114,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) // Get Authentication Vectors from HSS if (!m_hss->gen_auth_info_answer(imsi, m_sec_ctx.k_asme, m_sec_ctx.autn, m_sec_ctx.rand, m_sec_ctx.xres)) { srslte::console("User not found. IMSI %015" PRIu64 "\n", imsi); - m_nas_log->info("User not found. IMSI %015" PRIu64 "\n", imsi); + m_logger.info("User not found. IMSI %015" PRIu64 "", imsi); return false; } // Identity reponse from unknown GUTI atach. Assigning new eKSI. @@ -1124,7 +1123,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) // Make sure UE context was not previously stored in IMSI map nas* nas_ctx = m_s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx != nullptr) { - m_nas_log->warning("UE context already exists.\n"); + m_logger.warning("UE context already exists."); m_s1ap->delete_ue_ctx(imsi); } @@ -1139,7 +1138,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) m_s1ap->send_downlink_nas_transport(m_ecm_ctx.enb_ue_s1ap_id, m_ecm_ctx.mme_ue_s1ap_id, nas_tx, m_ecm_ctx.enb_sri); m_pool->deallocate(nas_tx); - m_nas_log->info("Downlink NAS: Sent Authentication Request\n"); + m_logger.info("Downlink NAS: Sent Authentication Request"); srslte::console("Downlink NAS: Sent Authentication Request\n"); return true; } @@ -1147,7 +1146,7 @@ bool nas::handle_identity_response(srslte::byte_buffer_t* nas_rx) bool nas::handle_tracking_area_update_request(srslte::byte_buffer_t* nas_rx) { srslte::console("Warning: Tracking Area Update Request messages not handled yet.\n"); - m_nas_log->warning("Warning: Tracking Area Update Request messages not handled yet.\n"); + m_logger.warning("Warning: Tracking Area Update Request messages not handled yet."); srslte::byte_buffer_pool* pool = srslte::byte_buffer_pool::get_instance(); srslte::byte_buffer_t* nas_tx; @@ -1166,7 +1165,7 @@ bool nas::handle_tracking_area_update_request(srslte::byte_buffer_t* nas_rx) bool nas::handle_authentication_failure(srslte::byte_buffer_t* nas_rx) { - m_nas_log->info("Received Authentication Failure\n"); + m_logger.info("Received Authentication Failure"); srslte::byte_buffer_t* nas_tx; LIBLTE_MME_AUTHENTICATION_FAILURE_MSG_STRUCT auth_fail; @@ -1174,36 +1173,36 @@ bool nas::handle_authentication_failure(srslte::byte_buffer_t* nas_rx) err = liblte_mme_unpack_authentication_failure_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_rx, &auth_fail); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error unpacking NAS authentication failure. Error: %s\n", liblte_error_text[err]); + m_logger.error("Error unpacking NAS authentication failure. Error: %s", liblte_error_text[err]); return false; } switch (auth_fail.emm_cause) { case 20: srslte::console("MAC code failure\n"); - m_nas_log->info("MAC code failure\n"); + m_logger.info("MAC code failure"); break; case 26: srslte::console("Non-EPS authentication unacceptable\n"); - m_nas_log->info("Non-EPS authentication unacceptable\n"); + m_logger.info("Non-EPS authentication unacceptable"); break; case 21: srslte::console("Authentication Failure -- Synchronization Failure\n"); - m_nas_log->info("Authentication Failure -- Synchronization Failure\n"); + m_logger.info("Authentication Failure -- Synchronization Failure"); if (auth_fail.auth_fail_param_present == false) { - m_nas_log->error("Missing fail parameter\n"); + m_logger.error("Missing fail parameter"); return false; } if (!m_hss->resync_sqn(m_emm_ctx.imsi, auth_fail.auth_fail_param)) { srslte::console("Resynchronization failed. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info("Resynchronization failed. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); + m_logger.info("Resynchronization failed. IMSI %015" PRIu64 "", m_emm_ctx.imsi); return false; } // Get Authentication Vectors from HSS if (!m_hss->gen_auth_info_answer( m_emm_ctx.imsi, m_sec_ctx.k_asme, m_sec_ctx.autn, m_sec_ctx.rand, m_sec_ctx.xres)) { srslte::console("User not found. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info("User not found. IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); + m_logger.info("User not found. IMSI %015" PRIu64 "", m_emm_ctx.imsi); return false; } @@ -1219,7 +1218,7 @@ bool nas::handle_authentication_failure(srslte::byte_buffer_t* nas_rx) m_ecm_ctx.enb_ue_s1ap_id, m_ecm_ctx.mme_ue_s1ap_id, nas_tx, m_ecm_ctx.enb_sri); m_pool->deallocate(nas_tx); - m_nas_log->info("Downlink NAS: Sent Authentication Request\n"); + m_logger.info("Downlink NAS: Sent Authentication Request"); srslte::console("Downlink NAS: Sent Authentication Request\n"); // TODO Start T3460 Timer! break; @@ -1231,12 +1230,12 @@ bool nas::handle_detach_request(srslte::byte_buffer_t* nas_msg) { srslte::console("Detach request -- IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); - m_nas_log->info("Detach request -- IMSI %015" PRIu64 "\n", m_emm_ctx.imsi); + m_logger.info("Detach request -- IMSI %015" PRIu64 "", m_emm_ctx.imsi); LIBLTE_MME_DETACH_REQUEST_MSG_STRUCT detach_req; LIBLTE_ERROR_ENUM err = liblte_mme_unpack_detach_request_msg((LIBLTE_BYTE_MSG_STRUCT*)nas_msg, &detach_req); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Could not unpack detach request\n"); + m_logger.error("Could not unpack detach request"); return false; } @@ -1257,7 +1256,7 @@ bool nas::handle_detach_request(srslte::byte_buffer_t* nas_msg) /*Packing/Unpacking helper functions*/ bool nas::pack_authentication_request(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing Authentication Request\n"); + m_logger.info("Packing Authentication Request"); // Pack NAS msg LIBLTE_MME_AUTHENTICATION_REQUEST_MSG_STRUCT auth_req; @@ -1268,7 +1267,7 @@ bool nas::pack_authentication_request(srslte::byte_buffer_t* nas_buffer) LIBLTE_ERROR_ENUM err = liblte_mme_pack_authentication_request_msg(&auth_req, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing Authentication Request\n"); + m_logger.error("Error packing Authentication Request"); srslte::console("Error packing Authentication Request\n"); return false; } @@ -1277,12 +1276,12 @@ bool nas::pack_authentication_request(srslte::byte_buffer_t* nas_buffer) bool nas::pack_authentication_reject(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing Authentication Reject\n"); + m_logger.info("Packing Authentication Reject"); LIBLTE_MME_AUTHENTICATION_REJECT_MSG_STRUCT auth_rej; LIBLTE_ERROR_ENUM err = liblte_mme_pack_authentication_reject_msg(&auth_rej, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing Authentication Reject\n"); + m_logger.error("Error packing Authentication Reject"); srslte::console("Error packing Authentication Reject\n"); return false; } @@ -1291,7 +1290,7 @@ bool nas::pack_authentication_reject(srslte::byte_buffer_t* nas_buffer) bool nas::pack_security_mode_command(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing Security Mode Command\n"); + m_logger.info("Packing Security Mode Command"); // Pack NAS PDU LIBLTE_MME_SECURITY_MODE_COMMAND_MSG_STRUCT sm_cmd; @@ -1331,14 +1330,14 @@ bool nas::pack_security_mode_command(srslte::byte_buffer_t* nas_buffer) srslte::security_generate_k_nas( m_sec_ctx.k_asme, m_sec_ctx.cipher_algo, m_sec_ctx.integ_algo, m_sec_ctx.k_nas_enc, m_sec_ctx.k_nas_int); - m_nas_log->info_hex(m_sec_ctx.k_nas_enc, 32, "Key NAS Encryption (k_nas_enc)\n"); - m_nas_log->info_hex(m_sec_ctx.k_nas_int, 32, "Key NAS Integrity (k_nas_int)\n"); + m_logger.info(m_sec_ctx.k_nas_enc, 32, "Key NAS Encryption (k_nas_enc)"); + m_logger.info(m_sec_ctx.k_nas_int, 32, "Key NAS Integrity (k_nas_int)"); uint8_t key_enb[32]; srslte::security_generate_k_enb(m_sec_ctx.k_asme, m_sec_ctx.ul_nas_count, m_sec_ctx.k_enb); - m_nas_log->info("Generating KeNB with UL NAS COUNT: %d\n", m_sec_ctx.ul_nas_count); + m_logger.info("Generating KeNB with UL NAS COUNT: %d", m_sec_ctx.ul_nas_count); srslte::console("Generating KeNB with UL NAS COUNT: %d\n", m_sec_ctx.ul_nas_count); - m_nas_log->info_hex(m_sec_ctx.k_enb, 32, "Key eNodeB (k_enb)\n"); + m_logger.info(m_sec_ctx.k_enb, 32, "Key eNodeB (k_enb)"); // Generate MAC for integrity protection uint8_t mac[4]; @@ -1349,7 +1348,7 @@ bool nas::pack_security_mode_command(srslte::byte_buffer_t* nas_buffer) bool nas::pack_esm_information_request(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing ESM Information request\n"); + m_logger.info("Packing ESM Information request"); LIBLTE_MME_ESM_INFORMATION_REQUEST_MSG_STRUCT esm_info_req; esm_info_req.eps_bearer_id = 0; @@ -1361,7 +1360,7 @@ bool nas::pack_esm_information_request(srslte::byte_buffer_t* nas_buffer) LIBLTE_ERROR_ENUM err = srslte_mme_pack_esm_information_request_msg( &esm_info_req, sec_hdr_type, m_sec_ctx.dl_nas_count, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing ESM information request\n"); + m_logger.error("Error packing ESM information request"); srslte::console("Error packing ESM information request\n"); return false; } @@ -1376,7 +1375,7 @@ bool nas::pack_esm_information_request(srslte::byte_buffer_t* nas_buffer) bool nas::pack_attach_accept(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing Attach Accept\n"); + m_logger.info("Packing Attach Accept"); LIBLTE_MME_ATTACH_ACCEPT_MSG_STRUCT attach_accept; LIBLTE_MME_ACTIVATE_DEFAULT_EPS_BEARER_CONTEXT_REQUEST_MSG_STRUCT act_def_eps_bearer_context_req; @@ -1411,7 +1410,7 @@ bool nas::pack_attach_accept(srslte::byte_buffer_t* nas_buffer) attach_accept.tai_list.tai[0].mnc = mnc; attach_accept.tai_list.tai[0].tac = m_tac; - m_nas_log->info("Attach Accept -- MCC 0x%x, MNC 0x%x\n", m_mcc, m_mnc); + m_logger.info("Attach Accept -- MCC 0x%x, MNC 0x%x", m_mcc, m_mnc); // Allocate a GUTI ot the UE attach_accept.guti_present = true; @@ -1421,12 +1420,12 @@ bool nas::pack_attach_accept(srslte::byte_buffer_t* nas_buffer) attach_accept.guti.guti.mme_group_id = m_mme_group; attach_accept.guti.guti.mme_code = m_mme_code; attach_accept.guti.guti.m_tmsi = m_s1ap->allocate_m_tmsi(m_emm_ctx.imsi); - m_nas_log->debug("Allocated GUTI: MCC %d, MNC %d, MME Group Id %d, MME Code 0x%x, M-TMSI 0x%x\n", - attach_accept.guti.guti.mcc, - attach_accept.guti.guti.mnc, - attach_accept.guti.guti.mme_group_id, - attach_accept.guti.guti.mme_code, - attach_accept.guti.guti.m_tmsi); + m_logger.debug("Allocated GUTI: MCC %d, MNC %d, MME Group Id %d, MME Code 0x%x, M-TMSI 0x%x", + attach_accept.guti.guti.mcc, + attach_accept.guti.guti.mnc, + attach_accept.guti.guti.mme_group_id, + attach_accept.guti.guti.mme_code, + attach_accept.guti.guti.m_tmsi); memcpy(&m_sec_ctx.guti, &attach_accept.guti, sizeof(LIBLTE_MME_EPS_MOBILE_ID_GUTI_STRUCT)); @@ -1501,20 +1500,20 @@ bool nas::pack_attach_accept(srslte::byte_buffer_t* nas_buffer) memcpy(&nas_buffer->msg[1], mac, 4); // Log attach accept info - m_nas_log->info("Packed Attach Accept\n"); + m_logger.info("Packed Attach Accept"); return true; } bool nas::pack_identity_request(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing Identity Request\n"); + m_logger.info("Packing Identity Request"); LIBLTE_MME_ID_REQUEST_MSG_STRUCT id_req; id_req.id_type = LIBLTE_MME_EPS_MOBILE_ID_TYPE_IMSI; LIBLTE_ERROR_ENUM err = liblte_mme_pack_identity_request_msg(&id_req, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing Identity Request\n"); - srslte::console("Error packing Identity REquest\n"); + m_logger.error("Error packing Identity Request"); + srslte::console("Error packing Identity Request\n"); return false; } return true; @@ -1522,7 +1521,7 @@ bool nas::pack_identity_request(srslte::byte_buffer_t* nas_buffer) bool nas::pack_emm_information(srslte::byte_buffer_t* nas_buffer) { - m_nas_log->info("Packing EMM Information\n"); + m_logger.info("Packing EMM Information"); LIBLTE_MME_EMM_INFORMATION_MSG_STRUCT emm_info; emm_info.full_net_name_present = true; @@ -1548,7 +1547,7 @@ bool nas::pack_emm_information(srslte::byte_buffer_t* nas_buffer) emm_info.utc_and_local_time_zone.tz = 0; emm_info.utc_and_local_time_zone_present = true; } else { - m_nas_log->error("Error getting current time: %s\n", strerror(errno)); + m_logger.error("Error getting current time: %s", strerror(errno)); } uint8_t sec_hdr_type = LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED; @@ -1556,7 +1555,7 @@ bool nas::pack_emm_information(srslte::byte_buffer_t* nas_buffer) LIBLTE_ERROR_ENUM err = liblte_mme_pack_emm_information_msg( &emm_info, sec_hdr_type, m_sec_ctx.dl_nas_count, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing EMM Information\n"); + m_logger.error("Error packing EMM Information"); srslte::console("Error packing EMM Information\n"); return false; } @@ -1569,7 +1568,7 @@ bool nas::pack_emm_information(srslte::byte_buffer_t* nas_buffer) integrity_generate(nas_buffer, mac); memcpy(&nas_buffer->msg[1], mac, 4); - m_nas_log->info("Packed UE EMM information\n"); + m_logger.info("Packed UE EMM information"); return true; } @@ -1586,7 +1585,7 @@ bool nas::pack_service_reject(srslte::byte_buffer_t* nas_buffer, uint8_t emm_cau LIBLTE_ERROR_ENUM err = liblte_mme_pack_service_reject_msg( &service_rej, LIBLTE_MME_SECURITY_HDR_TYPE_PLAIN_NAS, 0, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing Service Reject\n"); + m_logger.error("Error packing Service Reject"); srslte::console("Error packing Service Reject\n"); return false; } @@ -1602,13 +1601,13 @@ bool nas::pack_tracking_area_update_reject(srslte::byte_buffer_t* nas_buffer, ui if (emm_cause == LIBLTE_MME_EMM_CAUSE_CONGESTION) { // Standard would want T3446 set in this case - m_nas_log->error("Tracking Area Update Reject EMM Cause set to \"CONGESTION\", but back-off timer not set.\n"); + m_logger.error("Tracking Area Update Reject EMM Cause set to \"CONGESTION\", but back-off timer not set."); } LIBLTE_ERROR_ENUM err = liblte_mme_pack_tracking_area_update_reject_msg( &tau_rej, LIBLTE_MME_SECURITY_HDR_TYPE_PLAIN_NAS, 0, (LIBLTE_BYTE_MSG_STRUCT*)nas_buffer); if (err != LIBLTE_SUCCESS) { - m_nas_log->error("Error packing Tracking Area Update Reject\n"); + m_logger.error("Error packing Tracking Area Update Reject"); srslte::console("Error packing Tracking Area Update Reject\n"); return false; } @@ -1627,7 +1626,7 @@ bool nas::short_integrity_check(srslte::byte_buffer_t* pdu) int i; if (pdu->N_bytes < 4) { - m_nas_log->warning("NAS message to short for short integrity check (pdu len: %d)", pdu->N_bytes); + m_logger.warning("NAS message to short for short integrity check (pdu len: %d)", pdu->N_bytes); return false; } @@ -1667,21 +1666,20 @@ bool nas::short_integrity_check(srslte::byte_buffer_t* pdu) // Check if expected mac equals the sent mac for (i = 0; i < 2; i++) { if (exp_mac[i + 2] != mac[i]) { - m_nas_log->warning("Short integrity check failure. Local: count=%d, [%02x %02x %02x %02x], " - "Received: count=%d, [%02x %02x]\n", - m_sec_ctx.ul_nas_count, - exp_mac[0], - exp_mac[1], - exp_mac[2], - exp_mac[3], - pdu->msg[1] & 0x1F, - mac[0], - mac[1]); + m_logger.warning("Short integrity check failure. Local: count=%d, [%02x %02x %02x %02x], " + "Received: count=%d, [%02x %02x]", + m_sec_ctx.ul_nas_count, + exp_mac[0], + exp_mac[1], + exp_mac[2], + exp_mac[3], + pdu->msg[1] & 0x1F, + mac[0], + mac[1]); return false; } } - m_nas_log->info( - "Integrity check ok. Local: count=%d, Received: count=%d\n", m_sec_ctx.ul_nas_count, pdu->msg[1] & 0x1F); + m_logger.info("Integrity check ok. Local: count=%d, Received: count=%d", m_sec_ctx.ul_nas_count, pdu->msg[1] & 0x1F); return true; } @@ -1728,24 +1726,24 @@ bool nas::integrity_check(srslte::byte_buffer_t* pdu) // Check if expected mac equals the sent mac for (int i = 0; i < 4; i++) { if (exp_mac[i] != mac[i]) { - m_nas_log->warning("Integrity check failure. Algorithm=EIA%d\n", (int)m_sec_ctx.integ_algo); - m_nas_log->warning("UL Local: est_count=%d, old_count=%d, MAC=[%02x %02x %02x %02x], " - "Received: UL count=%d, MAC=[%02x %02x %02x %02x]\n", - estimated_count, - m_sec_ctx.ul_nas_count, - exp_mac[0], - exp_mac[1], - exp_mac[2], - exp_mac[3], - pdu->msg[5], - mac[0], - mac[1], - mac[2], - mac[3]); + m_logger.warning("Integrity check failure. Algorithm=EIA%d", (int)m_sec_ctx.integ_algo); + m_logger.warning("UL Local: est_count=%d, old_count=%d, MAC=[%02x %02x %02x %02x], " + "Received: UL count=%d, MAC=[%02x %02x %02x %02x]", + estimated_count, + m_sec_ctx.ul_nas_count, + exp_mac[0], + exp_mac[1], + exp_mac[2], + exp_mac[3], + pdu->msg[5], + mac[0], + mac[1], + mac[2], + mac[3]); return false; } } - m_nas_log->info("Integrity check ok. Local: count=%d, Received: count=%d\n", estimated_count, pdu->msg[5]); + m_logger.info("Integrity check ok. Local: count=%d, Received: count=%d", estimated_count, pdu->msg[5]); m_sec_ctx.ul_nas_count = estimated_count; return true; @@ -1786,9 +1784,9 @@ void nas::integrity_generate(srslte::byte_buffer_t* pdu, uint8_t* mac) default: break; } - m_nas_log->debug("Generating MAC with inputs: Algorithm %s, DL COUNT %d\n", - srslte::integrity_algorithm_id_text[m_sec_ctx.integ_algo], - m_sec_ctx.dl_nas_count); + m_logger.debug("Generating MAC with inputs: Algorithm %s, DL COUNT %d", + srslte::integrity_algorithm_id_text[m_sec_ctx.integ_algo], + m_sec_ctx.dl_nas_count); } void nas::cipher_decrypt(srslte::byte_buffer_t* pdu) @@ -1806,7 +1804,7 @@ void nas::cipher_decrypt(srslte::byte_buffer_t* pdu) pdu->N_bytes - 6, &tmp_pdu.msg[6]); memcpy(&pdu->msg[6], &tmp_pdu.msg[6], pdu->N_bytes - 6); - m_nas_log->debug_hex(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); + m_logger.debug(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); break; case srslte::CIPHERING_ALGORITHM_ID_128_EEA2: srslte::security_128_eea2(&m_sec_ctx.k_nas_enc[16], @@ -1816,7 +1814,7 @@ void nas::cipher_decrypt(srslte::byte_buffer_t* pdu) &pdu->msg[6], pdu->N_bytes - 6, &tmp_pdu.msg[6]); - m_nas_log->debug_hex(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); + m_logger.debug(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); memcpy(&pdu->msg[6], &tmp_pdu.msg[6], pdu->N_bytes - 6); break; case srslte::CIPHERING_ALGORITHM_ID_128_EEA3: @@ -1827,11 +1825,11 @@ void nas::cipher_decrypt(srslte::byte_buffer_t* pdu) &pdu->msg[6], pdu->N_bytes - 6, &tmp_pdu.msg[6]); - m_nas_log->debug_hex(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); + m_logger.debug(tmp_pdu.msg, pdu->N_bytes, "Decrypted"); memcpy(&pdu->msg[6], &tmp_pdu.msg[6], pdu->N_bytes - 6); break; default: - m_nas_log->error("Ciphering algorithms not known\n"); + m_logger.error("Ciphering algorithms not known"); break; } } @@ -1851,7 +1849,7 @@ void nas::cipher_encrypt(srslte::byte_buffer_t* pdu) pdu->N_bytes - 6, &pdu_tmp.msg[6]); memcpy(&pdu->msg[6], &pdu_tmp.msg[6], pdu->N_bytes - 6); - m_nas_log->debug_hex(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); + m_logger.debug(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); break; case srslte::CIPHERING_ALGORITHM_ID_128_EEA2: srslte::security_128_eea2(&m_sec_ctx.k_nas_enc[16], @@ -1862,7 +1860,7 @@ void nas::cipher_encrypt(srslte::byte_buffer_t* pdu) pdu->N_bytes - 6, &pdu_tmp.msg[6]); memcpy(&pdu->msg[6], &pdu_tmp.msg[6], pdu->N_bytes - 6); - m_nas_log->debug_hex(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); + m_logger.debug(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); break; case srslte::CIPHERING_ALGORITHM_ID_128_EEA3: srslte::security_128_eea3(&m_sec_ctx.k_nas_enc[16], @@ -1873,10 +1871,10 @@ void nas::cipher_encrypt(srslte::byte_buffer_t* pdu) pdu->N_bytes - 6, &pdu_tmp.msg[6]); memcpy(&pdu->msg[6], &pdu_tmp.msg[6], pdu->N_bytes - 6); - m_nas_log->debug_hex(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); + m_logger.debug(pdu_tmp.msg, pdu->N_bytes, "Encrypted"); break; default: - m_nas_log->error("Ciphering algorithm not known\n"); + m_logger.error("Ciphering algorithm not known"); break; } } @@ -1888,28 +1886,28 @@ void nas::cipher_encrypt(srslte::byte_buffer_t* pdu) **************************/ bool nas::start_timer(enum nas_timer_type type) { - m_nas_log->debug("Starting NAS timer\n"); + m_logger.debug("Starting NAS timer"); bool err = false; switch (type) { case T_3413: err = start_t3413(); break; default: - m_nas_log->error("Invalid timer type\n"); + m_logger.error("Invalid timer type"); } return err; } bool nas::expire_timer(enum nas_timer_type type) { - m_nas_log->debug("NAS timer expired\n"); + m_logger.debug("NAS timer expired"); bool err = false; switch (type) { case T_3413: err = expire_t3413(); break; default: - m_nas_log->error("Invalid timer type\n"); + m_logger.error("Invalid timer type"); } return err; } @@ -1917,15 +1915,15 @@ bool nas::expire_timer(enum nas_timer_type type) // T3413 -> Paging timer bool nas::start_t3413() { - m_nas_log->info("Starting T3413 Timer: Timeout value %d\n", m_t3413); + m_logger.info("Starting T3413 Timer: Timeout value %d", m_t3413); if (m_emm_ctx.state != EMM_STATE_REGISTERED) { - m_nas_log->error("EMM invalid status to start T3413\n"); + m_logger.error("EMM invalid status to start T3413"); return false; } int fdt = timerfd_create(CLOCK_MONOTONIC, 0); if (fdt < 0) { - m_nas_log->error("Error creating timer. %s\n", strerror(errno)); + m_logger.error("Error creating timer. %s", strerror(errno)); return false; } struct itimerspec t_value; @@ -1935,7 +1933,7 @@ bool nas::start_t3413() t_value.it_interval.tv_nsec = 0; if (timerfd_settime(fdt, 0, &t_value, NULL) == -1) { - m_nas_log->error("Could not set timer\n"); + m_logger.error("Could not set timer"); close(fdt); return false; } @@ -1946,10 +1944,10 @@ bool nas::start_t3413() bool nas::expire_t3413() { - m_nas_log->info("T3413 expired -- Could not page the ue.\n"); + m_logger.info("T3413 expired -- Could not page the ue."); srslte::console("T3413 expired -- Could not page the ue.\n"); if (m_emm_ctx.state != EMM_STATE_REGISTERED) { - m_nas_log->error("EMM invalid status upon T3413 expiration\n"); + m_logger.error("EMM invalid status upon T3413 expiration"); return false; } // Send Paging Failure to the SPGW diff --git a/srsepc/src/mme/s1ap.cc b/srsepc/src/mme/s1ap.cc index 42d807033..66c0f38a6 100644 --- a/srsepc/src/mme/s1ap.cc +++ b/srsepc/src/mme/s1ap.cc @@ -52,7 +52,7 @@ void s1ap::cleanup(void) pthread_mutex_unlock(&s1ap_instance_mutex); } -int s1ap::init(s1ap_args_t s1ap_args, srslte::log_filter* nas_log, srslte::log_filter* s1ap_log) +int s1ap::init(s1ap_args_t s1ap_args) { m_pool = srslte::byte_buffer_pool::get_instance(); @@ -60,10 +60,6 @@ int s1ap::init(s1ap_args_t s1ap_args, srslte::log_filter* nas_log, srslte::log_f srslte::s1ap_mccmnc_to_plmn(s1ap_args.mcc, s1ap_args.mnc, &m_plmn); m_next_m_tmsi = rand(); - // Init log - m_nas_log = nas_log; - m_s1ap_log = s1ap_log; - // Get pointer to the HSS m_hss = hss::get_instance(); @@ -89,7 +85,7 @@ int s1ap::init(s1ap_args_t s1ap_args, srslte::log_filter* nas_log, srslte::log_f if (m_pcap_enable) { m_pcap.open(s1ap_args.pcap_filename.c_str()); } - m_s1ap_log->info("S1AP Initialized\n"); + m_logger.info("S1AP Initialized"); return 0; } @@ -100,7 +96,7 @@ void s1ap::stop() } std::map::iterator enb_it = m_active_enbs.begin(); while (enb_it != m_active_enbs.end()) { - m_s1ap_log->info("Deleting eNB context. eNB Id: 0x%x\n", enb_it->second->enb_id); + m_logger.info("Deleting eNB context. eNB Id: 0x%x", enb_it->second->enb_id); srslte::console("Deleting eNB context. eNB Id: 0x%x\n", enb_it->second->enb_id); delete enb_it->second; m_active_enbs.erase(enb_it++); @@ -108,7 +104,7 @@ void s1ap::stop() std::map::iterator ue_it = m_imsi_to_nas_ctx.begin(); while (ue_it != m_imsi_to_nas_ctx.end()) { - m_s1ap_log->info("Deleting UE EMM context. IMSI: %015" PRIu64 "\n", ue_it->first); + m_logger.info("Deleting UE EMM context. IMSI: %015" PRIu64 "", ue_it->first); srslte::console("Deleting UE EMM context. IMSI: %015" PRIu64 "\n", ue_it->first); delete ue_it->second; m_imsi_to_nas_ctx.erase(ue_it++); @@ -143,7 +139,7 @@ int s1ap::enb_listen() struct sockaddr_in s1mme_addr; struct sctp_event_subscribe evnts; - m_s1ap_log->info("S1-MME Initializing\n"); + m_logger.info("S1-MME Initializing"); sock_fd = socket(AF_INET, SOCK_SEQPACKET, IPPROTO_SCTP); if (sock_fd == -1) { srslte::console("Could not create SCTP socket\n"); @@ -169,7 +165,7 @@ int s1ap::enb_listen() err = bind(sock_fd, (struct sockaddr*)&s1mme_addr, sizeof(s1mme_addr)); if (err != 0) { close(sock_fd); - m_s1ap_log->error("Error binding SCTP socket\n"); + m_logger.error("Error binding SCTP socket"); srslte::console("Error binding SCTP socket\n"); return -1; } @@ -178,7 +174,7 @@ int s1ap::enb_listen() err = listen(sock_fd, SOMAXCONN); if (err != 0) { close(sock_fd); - m_s1ap_log->error("Error in SCTP socket listen\n"); + m_logger.error("Error in SCTP socket listen"); srslte::console("Error in SCTP socket listen\n"); return -1; } @@ -188,16 +184,16 @@ int s1ap::enb_listen() bool s1ap::s1ap_tx_pdu(const asn1::s1ap::s1ap_pdu_c& pdu, struct sctp_sndrcvinfo* enb_sri) { - m_s1ap_log->debug("Transmitting S1AP PDU. eNB SCTP association Id: %d\n", enb_sri->sinfo_assoc_id); + m_logger.debug("Transmitting S1AP PDU. eNB SCTP association Id: %d", enb_sri->sinfo_assoc_id); srslte::unique_byte_buffer_t buf = srslte::allocate_unique_buffer(*m_pool); if (buf == nullptr) { - m_s1ap_log->error("Fatal Error: Couldn't allocate buffer for S1AP PDU.\n"); + m_logger.error("Fatal Error: Couldn't allocate buffer for S1AP PDU."); return false; } asn1::bit_ref bref(buf->msg, buf->get_tailroom()); if (pdu.pack(bref) != asn1::SRSASN_SUCCESS) { - m_s1ap_log->error("Could not pack S1AP PDU correctly.\n"); + m_logger.error("Could not pack S1AP PDU correctly."); return false; } buf->N_bytes = bref.distance_bytes(); @@ -205,7 +201,7 @@ bool s1ap::s1ap_tx_pdu(const asn1::s1ap::s1ap_pdu_c& pdu, struct sctp_sndrcvinfo ssize_t n_sent = sctp_send(m_s1mme, buf->msg, buf->N_bytes, enb_sri, MSG_NOSIGNAL); if (n_sent == -1) { srslte::console("Failed to send S1AP PDU. Error: %s\n", strerror(errno)); - m_s1ap_log->error("Failed to send S1AP PDU. Error: %s \n", strerror(errno)); + m_logger.error("Failed to send S1AP PDU. Error: %s ", strerror(errno)); return false; } @@ -227,25 +223,25 @@ void s1ap::handle_s1ap_rx_pdu(srslte::byte_buffer_t* pdu, struct sctp_sndrcvinfo s1ap_pdu_t rx_pdu; asn1::cbit_ref bref(pdu->msg, pdu->N_bytes); if (rx_pdu.unpack(bref) != asn1::SRSASN_SUCCESS) { - m_s1ap_log->error("Failed to unpack received PDU\n"); + m_logger.error("Failed to unpack received PDU"); return; } switch (rx_pdu.type().value) { case s1ap_pdu_t::types_opts::init_msg: - m_s1ap_log->info("Received Initiating PDU\n"); + m_logger.info("Received Initiating PDU"); handle_initiating_message(rx_pdu.init_msg(), enb_sri); break; case s1ap_pdu_t::types_opts::successful_outcome: - m_s1ap_log->info("Received Succeseful Outcome PDU\n"); + m_logger.info("Received Succeseful Outcome PDU"); handle_successful_outcome(rx_pdu.successful_outcome()); break; case s1ap_pdu_t::types_opts::unsuccessful_outcome: - m_s1ap_log->info("Received Unsucceseful Outcome PDU\n"); + m_logger.info("Received Unsucceseful Outcome PDU"); // TODO handle_unsuccessfuloutcome(&rx_pdu.choice.unsuccessfulOutcome); break; default: - m_s1ap_log->error("Unhandled PDU type %d\n", rx_pdu.type().value); + m_logger.error("Unhandled PDU type %d", rx_pdu.type().value); } } @@ -255,23 +251,23 @@ void s1ap::handle_initiating_message(const asn1::s1ap::init_msg_s& msg, struct s switch (msg.value.type().value) { case init_msg_type_opts_t::s1_setup_request: - m_s1ap_log->info("Received S1 Setup Request.\n"); + m_logger.info("Received S1 Setup Request."); m_s1ap_mngmt_proc->handle_s1_setup_request(msg.value.s1_setup_request(), enb_sri); break; case init_msg_type_opts_t::init_ue_msg: - m_s1ap_log->info("Received Initial UE Message.\n"); + m_logger.info("Received Initial UE Message."); m_s1ap_nas_transport->handle_initial_ue_message(msg.value.init_ue_msg(), enb_sri); break; case init_msg_type_opts_t::ul_nas_transport: - m_s1ap_log->info("Received Uplink NAS Transport Message.\n"); + m_logger.info("Received Uplink NAS Transport Message."); m_s1ap_nas_transport->handle_uplink_nas_transport(msg.value.ul_nas_transport(), enb_sri); break; case init_msg_type_opts_t::ue_context_release_request: - m_s1ap_log->info("Received UE Context Release Request Message.\n"); + m_logger.info("Received UE Context Release Request Message."); m_s1ap_ctx_mngmt_proc->handle_ue_context_release_request(msg.value.ue_context_release_request(), enb_sri); break; default: - m_s1ap_log->error("Unhandled S1AP intiating message: %s\n", msg.value.type().to_string().c_str()); + m_logger.error("Unhandled S1AP intiating message: %s", msg.value.type().to_string().c_str()); srslte::console("Unhandled S1APintiating message: %s\n", msg.value.type().to_string().c_str()); } } @@ -282,22 +278,22 @@ void s1ap::handle_successful_outcome(const asn1::s1ap::successful_outcome_s& msg switch (msg.value.type().value) { case successful_outcome_type_opts_t::init_context_setup_resp: - m_s1ap_log->info("Received Initial Context Setup Response.\n"); + m_logger.info("Received Initial Context Setup Response."); m_s1ap_ctx_mngmt_proc->handle_initial_context_setup_response(msg.value.init_context_setup_resp()); break; case successful_outcome_type_opts_t::ue_context_release_complete: - m_s1ap_log->info("Received UE Context Release Complete\n"); + m_logger.info("Received UE Context Release Complete"); m_s1ap_ctx_mngmt_proc->handle_ue_context_release_complete(msg.value.ue_context_release_complete()); break; default: - m_s1ap_log->error("Unhandled successful outcome message: %s\n", msg.value.type().to_string().c_str()); + m_logger.error("Unhandled successful outcome message: %s", msg.value.type().to_string().c_str()); } } // eNB Context Managment void s1ap::add_new_enb_ctx(const enb_ctx_t& enb_ctx, const struct sctp_sndrcvinfo* enb_sri) { - m_s1ap_log->info("Adding new eNB context. eNB ID %d\n", enb_ctx.enb_id); + m_logger.info("Adding new eNB context. eNB ID %d", enb_ctx.enb_id); std::set ue_set; enb_ctx_t* enb_ptr = new enb_ctx_t; *enb_ptr = enb_ctx; @@ -323,11 +319,11 @@ void s1ap::delete_enb_ctx(int32_t assoc_id) std::map::iterator it_ctx = m_active_enbs.find(enb_id); if (it_ctx == m_active_enbs.end() || it_assoc == m_sctp_to_enb_id.end()) { - m_s1ap_log->error("Could not find eNB to delete. Association: %d\n", assoc_id); + m_logger.error("Could not find eNB to delete. Association: %d", assoc_id); return; } - m_s1ap_log->info("Deleting eNB context. eNB Id: 0x%x\n", enb_id); + m_logger.info("Deleting eNB context. eNB Id: 0x%x", enb_id); srslte::console("Deleting eNB context. eNB Id: 0x%x\n", enb_id); // Delete connected UEs ctx @@ -345,41 +341,41 @@ bool s1ap::add_nas_ctx_to_imsi_map(nas* nas_ctx) { std::map::iterator ctx_it = m_imsi_to_nas_ctx.find(nas_ctx->m_emm_ctx.imsi); if (ctx_it != m_imsi_to_nas_ctx.end()) { - m_s1ap_log->error("UE Context already exists. IMSI %015" PRIu64 "\n", nas_ctx->m_emm_ctx.imsi); + m_logger.error("UE Context already exists. IMSI %015" PRIu64 "", nas_ctx->m_emm_ctx.imsi); return false; } if (nas_ctx->m_ecm_ctx.mme_ue_s1ap_id != 0) { std::map::iterator ctx_it2 = m_mme_ue_s1ap_id_to_nas_ctx.find(nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); if (ctx_it2 != m_mme_ue_s1ap_id_to_nas_ctx.end() && ctx_it2->second != nas_ctx) { - m_s1ap_log->error("Context identified with IMSI does not match context identified by MME UE S1AP Id.\n"); + m_logger.error("Context identified with IMSI does not match context identified by MME UE S1AP Id."); return false; } } m_imsi_to_nas_ctx.insert(std::pair(nas_ctx->m_emm_ctx.imsi, nas_ctx)); - m_s1ap_log->debug("Saved UE context corresponding to IMSI %015" PRIu64 "\n", nas_ctx->m_emm_ctx.imsi); + m_logger.debug("Saved UE context corresponding to IMSI %015" PRIu64 "", nas_ctx->m_emm_ctx.imsi); return true; } bool s1ap::add_nas_ctx_to_mme_ue_s1ap_id_map(nas* nas_ctx) { if (nas_ctx->m_ecm_ctx.mme_ue_s1ap_id == 0) { - m_s1ap_log->error("Could not add UE context to MME UE S1AP map. MME UE S1AP ID 0 is not valid.\n"); + m_logger.error("Could not add UE context to MME UE S1AP map. MME UE S1AP ID 0 is not valid."); return false; } std::map::iterator ctx_it = m_mme_ue_s1ap_id_to_nas_ctx.find(nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); if (ctx_it != m_mme_ue_s1ap_id_to_nas_ctx.end()) { - m_s1ap_log->error("UE Context already exists. MME UE S1AP Id %015" PRIu64 "\n", nas_ctx->m_emm_ctx.imsi); + m_logger.error("UE Context already exists. MME UE S1AP Id %015" PRIu64 "", nas_ctx->m_emm_ctx.imsi); return false; } if (nas_ctx->m_emm_ctx.imsi != 0) { std::map::iterator ctx_it2 = m_mme_ue_s1ap_id_to_nas_ctx.find(nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); if (ctx_it2 != m_mme_ue_s1ap_id_to_nas_ctx.end() && ctx_it2->second != nas_ctx) { - m_s1ap_log->error("Context identified with MME UE S1AP Id does not match context identified by IMSI.\n"); + m_logger.error("Context identified with MME UE S1AP Id does not match context identified by IMSI."); return false; } } m_mme_ue_s1ap_id_to_nas_ctx.insert(std::pair(nas_ctx->m_ecm_ctx.mme_ue_s1ap_id, nas_ctx)); - m_s1ap_log->debug("Saved UE context corresponding to MME UE S1AP Id %d\n", nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); + m_logger.debug("Saved UE context corresponding to MME UE S1AP Id %d", nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); return true; } @@ -387,16 +383,16 @@ bool s1ap::add_ue_to_enb_set(int32_t enb_assoc, uint32_t mme_ue_s1ap_id) { std::map >::iterator ues_in_enb = m_enb_assoc_to_ue_ids.find(enb_assoc); if (ues_in_enb == m_enb_assoc_to_ue_ids.end()) { - m_s1ap_log->error("Could not find eNB from eNB SCTP association %d\n", enb_assoc); + m_logger.error("Could not find eNB from eNB SCTP association %d", enb_assoc); return false; } std::set::iterator ue_id = ues_in_enb->second.find(mme_ue_s1ap_id); if (ue_id != ues_in_enb->second.end()) { - m_s1ap_log->error("UE with MME UE S1AP Id already exists %d\n", mme_ue_s1ap_id); + m_logger.error("UE with MME UE S1AP Id already exists %d", mme_ue_s1ap_id); return false; } ues_in_enb->second.insert(mme_ue_s1ap_id); - m_s1ap_log->debug("Added UE with MME-UE S1AP Id %d to eNB with association %d\n", mme_ue_s1ap_id, enb_assoc); + m_logger.debug("Added UE with MME-UE S1AP Id %d to eNB with association %d", mme_ue_s1ap_id, enb_assoc); return true; } @@ -433,8 +429,8 @@ void s1ap::release_ues_ecm_ctx_in_enb(int32_t enb_assoc) emm_ctx_t* emm_ctx = &nas_ctx->second->m_emm_ctx; ecm_ctx_t* ecm_ctx = &nas_ctx->second->m_ecm_ctx; - m_s1ap_log->info( - "Releasing UE context. IMSI: %015" PRIu64 ", UE-MME S1AP Id: %d\n", emm_ctx->imsi, ecm_ctx->mme_ue_s1ap_id); + m_logger.info( + "Releasing UE context. IMSI: %015" PRIu64 ", UE-MME S1AP Id: %d", emm_ctx->imsi, ecm_ctx->mme_ue_s1ap_id); if (emm_ctx->state == EMM_STATE_REGISTERED) { m_mme_gtpc->send_delete_session_request(emm_ctx->imsi); emm_ctx->state = EMM_STATE_DEREGISTERED; @@ -452,7 +448,7 @@ bool s1ap::release_ue_ecm_ctx(uint32_t mme_ue_s1ap_id) { nas* nas_ctx = find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == NULL) { - m_s1ap_log->error("Cannot release UE ECM context, UE not found. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); + m_logger.error("Cannot release UE ECM context, UE not found. MME-UE S1AP Id: %d", mme_ue_s1ap_id); return false; } ecm_ctx_t* ecm_ctx = &nas_ctx->m_ecm_ctx; @@ -460,13 +456,13 @@ bool s1ap::release_ue_ecm_ctx(uint32_t mme_ue_s1ap_id) // Delete UE within eNB UE set std::map::iterator it = m_sctp_to_enb_id.find(ecm_ctx->enb_sri.sinfo_assoc_id); if (it == m_sctp_to_enb_id.end()) { - m_s1ap_log->error("Could not find eNB for UE release request.\n"); + m_logger.error("Could not find eNB for UE release request."); return false; } uint16_t enb_id = it->second; std::map >::iterator ue_set = m_enb_assoc_to_ue_ids.find(ecm_ctx->enb_sri.sinfo_assoc_id); if (ue_set == m_enb_assoc_to_ue_ids.end()) { - m_s1ap_log->error("Could not find the eNB's UEs.\n"); + m_logger.error("Could not find the eNB's UEs."); return false; } ue_set->second.erase(mme_ue_s1ap_id); @@ -477,7 +473,7 @@ bool s1ap::release_ue_ecm_ctx(uint32_t mme_ue_s1ap_id) ecm_ctx->mme_ue_s1ap_id = 0; ecm_ctx->enb_ue_s1ap_id = 0; - m_s1ap_log->info("Released UE ECM Context.\n"); + m_logger.info("Released UE ECM Context."); return true; } @@ -485,7 +481,7 @@ bool s1ap::delete_ue_ctx(uint64_t imsi) { nas* nas_ctx = find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { - m_s1ap_log->info("Cannot delete UE context, UE not found. IMSI: %" PRIu64 "\n", imsi); + m_logger.info("Cannot delete UE context, UE not found. IMSI: %" PRIu64 "", imsi); return false; } @@ -497,7 +493,7 @@ bool s1ap::delete_ue_ctx(uint64_t imsi) // Delete UE context m_imsi_to_nas_ctx.erase(imsi); delete nas_ctx; - m_s1ap_log->info("Deleted UE Context.\n"); + m_logger.info("Deleted UE Context."); return true; } @@ -506,22 +502,22 @@ void s1ap::activate_eps_bearer(uint64_t imsi, uint8_t ebi) { std::map::iterator ue_ctx_it = m_imsi_to_nas_ctx.find(imsi); if (ue_ctx_it == m_imsi_to_nas_ctx.end()) { - m_s1ap_log->error("Could not activate EPS bearer: Could not find UE context\n"); + m_logger.error("Could not activate EPS bearer: Could not find UE context"); return; } // Make sure NAS is active uint32_t mme_ue_s1ap_id = ue_ctx_it->second->m_ecm_ctx.mme_ue_s1ap_id; std::map::iterator it = m_mme_ue_s1ap_id_to_nas_ctx.find(mme_ue_s1ap_id); if (it == m_mme_ue_s1ap_id_to_nas_ctx.end()) { - m_s1ap_log->error("Could not activate EPS bearer: ECM context seems to be missing\n"); + m_logger.error("Could not activate EPS bearer: ECM context seems to be missing"); return; } ecm_ctx_t* ecm_ctx = &ue_ctx_it->second->m_ecm_ctx; esm_ctx_t* esm_ctx = &ue_ctx_it->second->m_esm_ctx[ebi]; if (esm_ctx->state != ERAB_CTX_SETUP) { - m_s1ap_log->error( - "Could not be activate EPS Bearer, bearer in wrong state: MME S1AP Id %d, EPS Bearer id %d, state %d\n", + m_logger.error( + "Could not be activate EPS Bearer, bearer in wrong state: MME S1AP Id %d, EPS Bearer id %d, state %d", mme_ue_s1ap_id, ebi, esm_ctx->state); @@ -535,7 +531,7 @@ void s1ap::activate_eps_bearer(uint64_t imsi, uint8_t ebi) esm_ctx->state = ERAB_ACTIVE; ecm_ctx->state = ECM_STATE_CONNECTED; - m_s1ap_log->info("Activated EPS Bearer: Bearer id %d\n", ebi); + m_logger.info("Activated EPS Bearer: Bearer id %d", ebi); return; } @@ -545,7 +541,7 @@ uint32_t s1ap::allocate_m_tmsi(uint64_t imsi) m_next_m_tmsi = (m_next_m_tmsi + 1) % UINT32_MAX; m_tmsi_to_imsi.insert(std::pair(m_tmsi, imsi)); - m_s1ap_log->debug("Allocated M-TMSI 0x%x to IMSI %015" PRIu64 ",\n", m_tmsi, imsi); + m_logger.debug("Allocated M-TMSI 0x%x to IMSI %015" PRIu64 ",", m_tmsi, imsi); return m_tmsi; } @@ -553,10 +549,10 @@ uint64_t s1ap::find_imsi_from_m_tmsi(uint32_t m_tmsi) { std::map::iterator it = m_tmsi_to_imsi.find(m_tmsi); if (it != m_tmsi_to_imsi.end()) { - m_s1ap_log->debug("Found IMSI %015" PRIu64 " from M-TMSI 0x%x\n", it->second, m_tmsi); + m_logger.debug("Found IMSI %015" PRIu64 " from M-TMSI 0x%x", it->second, m_tmsi); return it->second; } else { - m_s1ap_log->debug("Could not find IMSI from M-TMSI 0x%x\n", m_tmsi); + m_logger.debug("Could not find IMSI from M-TMSI 0x%x", m_tmsi); return 0; } } @@ -567,18 +563,18 @@ void s1ap::print_enb_ctx_info(const std::string& prefix, const enb_ctx_t& enb_ct if (enb_ctx.enb_name_present) { srslte::console("%s - eNB Name: %s, eNB id: 0x%x\n", prefix.c_str(), enb_ctx.enb_name.c_str(), enb_ctx.enb_id); - m_s1ap_log->info("%s - eNB Name: %s, eNB id: 0x%x\n", prefix.c_str(), enb_ctx.enb_name.c_str(), enb_ctx.enb_id); + m_logger.info("%s - eNB Name: %s, eNB id: 0x%x", prefix.c_str(), enb_ctx.enb_name.c_str(), enb_ctx.enb_id); } else { srslte::console("%s - eNB Id 0x%x\n", prefix.c_str(), enb_ctx.enb_id); - m_s1ap_log->info("%s - eNB Id 0x%x\n", prefix.c_str(), enb_ctx.enb_id); + m_logger.info("%s - eNB Id 0x%x", prefix.c_str(), enb_ctx.enb_id); } srslte::mcc_to_string(enb_ctx.mcc, &mcc_str); srslte::mnc_to_string(enb_ctx.mnc, &mnc_str); - m_s1ap_log->info("%s - MCC:%s, MNC:%s, PLMN: %d\n", prefix.c_str(), mcc_str.c_str(), mnc_str.c_str(), enb_ctx.plmn); + m_logger.info("%s - MCC:%s, MNC:%s, PLMN: %d", prefix.c_str(), mcc_str.c_str(), mnc_str.c_str(), enb_ctx.plmn); srslte::console("%s - MCC:%s, MNC:%s\n", prefix.c_str(), mcc_str.c_str(), mnc_str.c_str()); for (int i = 0; i < enb_ctx.nof_supported_ta; i++) { for (int j = 0; i < enb_ctx.nof_supported_ta; i++) { - m_s1ap_log->info("%s - TAC %d, B-PLMN 0x%x\n", prefix.c_str(), enb_ctx.tacs[i], enb_ctx.bplmns[i][j]); + m_logger.info("%s - TAC %d, B-PLMN 0x%x", prefix.c_str(), enb_ctx.tacs[i], enb_ctx.bplmns[i][j]); srslte::console("%s - TAC %d, B-PLMN 0x%x\n", prefix.c_str(), enb_ctx.tacs[i], enb_ctx.bplmns[i][j]); } } @@ -602,7 +598,7 @@ bool s1ap::send_initial_context_setup_request(uint64_t imsi, uint16_t erab_to_se { nas* nas_ctx = find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { - m_s1ap_log->error("Error finding NAS context when sending initial context Setup Request\n"); + m_logger.error("Error finding NAS context when sending initial context Setup Request"); return false; } m_s1ap_ctx_mngmt_proc->send_initial_context_setup_request(nas_ctx, erab_to_setup); @@ -614,7 +610,7 @@ bool s1ap::send_ue_context_release_command(uint32_t mme_ue_s1ap_id) { nas* nas_ctx = find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == NULL) { - m_s1ap_log->error("Error finding NAS context when sending UE Context Setup Release\n"); + m_logger.error("Error finding NAS context when sending UE Context Setup Release"); return false; } m_s1ap_ctx_mngmt_proc->send_ue_context_release_command(nas_ctx); @@ -652,7 +648,7 @@ bool s1ap::expire_nas_timer(enum nas_timer_type type, uint64_t imsi) { nas* nas_ctx = find_nas_ctx_from_imsi(imsi); if (nas_ctx == NULL) { - m_s1ap_log->error("Error finding NAS context to handle timer\n"); + m_logger.error("Error finding NAS context to handle timer"); return false; } bool err = nas_ctx->expire_timer(type); diff --git a/srsepc/src/mme/s1ap_ctx_mngmt_proc.cc b/srsepc/src/mme/s1ap_ctx_mngmt_proc.cc index b937f6595..6d9e83cc6 100644 --- a/srsepc/src/mme/s1ap_ctx_mngmt_proc.cc +++ b/srsepc/src/mme/s1ap_ctx_mngmt_proc.cc @@ -57,14 +57,13 @@ void s1ap_ctx_mngmt_proc::init() { m_s1ap = s1ap::get_instance(); m_mme_gtpc = mme_gtpc::get_instance(); - m_s1ap_log = m_s1ap->m_s1ap_log; m_s1ap_args = m_s1ap->m_s1ap_args; m_pool = srslte::byte_buffer_pool::get_instance(); } bool s1ap_ctx_mngmt_proc::send_initial_context_setup_request(nas* nas_ctx, uint16_t erab_to_setup) { - m_s1ap_log->info("Preparing to send Initial Context Setup request\n"); + m_logger.info("Preparing to send Initial Context Setup request"); // Get UE Context/E-RAB Context to setup emm_ctx_t* emm_ctx = &nas_ctx->m_emm_ctx; @@ -130,13 +129,13 @@ bool s1ap_ctx_mngmt_proc::send_initial_context_setup_request(nas* nas_ctx, uint1 for (uint8_t i = 0; i < 32; ++i) { in_ctx_req.security_key.value.data()[31 - i] = sec_ctx->k_enb[i]; } - m_s1ap_log->info_hex(sec_ctx->k_enb, 32, "Initial Context Setup Request -- Key eNB (k_enb)\n"); + m_logger.info(sec_ctx->k_enb, 32, "Initial Context Setup Request -- Key eNB (k_enb)"); srslte::unique_byte_buffer_t nas_buffer = allocate_unique_buffer(*m_pool); if (emm_ctx->state == EMM_STATE_DEREGISTERED) { // Attach procedure initiated from an attach request srslte::console("Adding attach accept to Initial Context Setup Request\n"); - m_s1ap_log->info("Adding attach accept to Initial Context Setup Request\n"); + m_logger.info("Adding attach accept to Initial Context Setup Request"); nas_ctx->pack_attach_accept(nas_buffer.get()); // Add nas message to context setup request @@ -146,7 +145,7 @@ bool s1ap_ctx_mngmt_proc::send_initial_context_setup_request(nas* nas_ctx, uint1 } if (!m_s1ap->s1ap_tx_pdu(tx_pdu, &ecm_ctx->enb_sri)) { - m_s1ap_log->error("Error sending Initial Context Setup Request.\n"); + m_logger.error("Error sending Initial Context Setup Request."); return false; } @@ -156,19 +155,19 @@ bool s1ap_ctx_mngmt_proc::send_initial_context_setup_request(nas* nas_ctx, uint1 struct in_addr addr; addr.s_addr = htonl(erab_ctx_req.transport_layer_address.to_number()); srslte::console("Sent Initial Context Setup Request. E-RAB id %d \n", erab_ctx_req.erab_id); - m_s1ap_log->info( - "Initial Context -- S1-U TEID 0x%" PRIx64 ". IP %s \n", erab_ctx_req.gtp_teid.to_number(), inet_ntoa(addr)); - m_s1ap_log->info("Initial Context Setup Request -- eNB UE S1AP Id %d, MME UE S1AP Id %" PRIu64 "\n", - in_ctx_req.enb_ue_s1ap_id.value.value, - in_ctx_req.mme_ue_s1ap_id.value.value); - m_s1ap_log->info("Initial Context Setup Request -- E-RAB id %d\n", erab_ctx_req.erab_id); - m_s1ap_log->info("Initial Context Setup Request -- S1-U TEID 0x%" PRIu64 ". IP %s \n", - erab_ctx_req.gtp_teid.to_number(), - inet_ntoa(addr)); - m_s1ap_log->info("Initial Context Setup Request -- S1-U TEID 0x%" PRIu64 ". IP %s \n", - erab_ctx_req.gtp_teid.to_number(), - inet_ntoa(addr)); - m_s1ap_log->info("Initial Context Setup Request -- QCI %d\n", erab_ctx_req.erab_level_qos_params.qci); + m_logger.info( + "Initial Context -- S1-U TEID 0x%" PRIx64 ". IP %s ", erab_ctx_req.gtp_teid.to_number(), inet_ntoa(addr)); + m_logger.info("Initial Context Setup Request -- eNB UE S1AP Id %d, MME UE S1AP Id %" PRIu64 "", + in_ctx_req.enb_ue_s1ap_id.value.value, + in_ctx_req.mme_ue_s1ap_id.value.value); + m_logger.info("Initial Context Setup Request -- E-RAB id %d", erab_ctx_req.erab_id); + m_logger.info("Initial Context Setup Request -- S1-U TEID 0x%" PRIu64 ". IP %s ", + erab_ctx_req.gtp_teid.to_number(), + inet_ntoa(addr)); + m_logger.info("Initial Context Setup Request -- S1-U TEID 0x%" PRIu64 ". IP %s ", + erab_ctx_req.gtp_teid.to_number(), + inet_ntoa(addr)); + m_logger.info("Initial Context Setup Request -- QCI %d", erab_ctx_req.erab_level_qos_params.qci); return true; } @@ -178,7 +177,7 @@ bool s1ap_ctx_mngmt_proc::handle_initial_context_setup_response( uint32_t mme_ue_s1ap_id = in_ctxt_resp.protocol_ies.mme_ue_s1ap_id.value.value; nas* nas_ctx = m_s1ap->find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == nullptr) { - m_s1ap_log->error("Could not find UE's context in active UE's map\n"); + m_logger.error("Could not find UE's context in active UE's map"); return false; } @@ -199,7 +198,7 @@ bool s1ap_ctx_mngmt_proc::handle_initial_context_setup_response( // Make sure we requested the context setup esm_ctx_t* esm_ctx = &nas_ctx->m_esm_ctx[erab_id]; if (esm_ctx->state != ERAB_CTX_REQUESTED) { - m_s1ap_log->error("E-RAB requested was not previously requested %d\n", erab_id); + m_logger.error("E-RAB requested was not previously requested %d", erab_id); return false; } @@ -215,11 +214,11 @@ bool s1ap_ctx_mngmt_proc::handle_initial_context_setup_response( tmp_addr.s_addr = esm_ctx->enb_fteid.ipv4; const char* err = inet_ntop(AF_INET, &tmp_addr, enb_addr_str, INET_ADDRSTRLEN); if (err == nullptr) { - m_s1ap_log->error("Error converting IP to string\n"); + m_logger.error("Error converting IP to string"); } - m_s1ap_log->info("E-RAB Context Setup. E-RAB id %d\n", esm_ctx->erab_id); - m_s1ap_log->info("E-RAB Context -- eNB TEID 0x%x, eNB Address %s\n", esm_ctx->enb_fteid.teid, enb_addr_str); + m_logger.info("E-RAB Context Setup. E-RAB id %d", esm_ctx->erab_id); + m_logger.info("E-RAB Context -- eNB TEID 0x%x, eNB Address %s", esm_ctx->enb_fteid.teid, enb_addr_str); srslte::console("E-RAB Context Setup. E-RAB id %d\n", esm_ctx->erab_id); srslte::console("E-RAB Context -- eNB TEID 0x%x; eNB GTP-U Address %s\n", esm_ctx->enb_fteid.teid, enb_addr_str); } @@ -236,12 +235,12 @@ bool s1ap_ctx_mngmt_proc::handle_ue_context_release_request(const asn1::s1ap::ue struct sctp_sndrcvinfo* enb_sri) { uint32_t mme_ue_s1ap_id = ue_rel.protocol_ies.mme_ue_s1ap_id.value.value; - m_s1ap_log->info("Received UE Context Release Request. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); + m_logger.info("Received UE Context Release Request. MME-UE S1AP Id: %d", mme_ue_s1ap_id); srslte::console("Received UE Context Release Request. MME-UE S1AP Id %d\n", mme_ue_s1ap_id); nas* nas_ctx = m_s1ap->find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == nullptr) { - m_s1ap_log->info("No UE context to release found. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); + m_logger.info("No UE context to release found. MME-UE S1AP Id: %d", mme_ue_s1ap_id); srslte::console("No UE context to release found. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); return false; } @@ -254,7 +253,7 @@ bool s1ap_ctx_mngmt_proc::handle_ue_context_release_request(const asn1::s1ap::ue send_ue_context_release_command(nas_ctx); } else { // No ECM Context to release - m_s1ap_log->info("UE is not ECM connected. No need to release S1-U. MME UE S1AP Id %d\n", mme_ue_s1ap_id); + m_logger.info("UE is not ECM connected. No need to release S1-U. MME UE S1AP Id %d", mme_ue_s1ap_id); // Make sure E-RABS are marked as DEACTIVATED. for (esm_ctx_t& esm_ctx : nas_ctx->m_esm_ctx) { esm_ctx.state = ERAB_DEACTIVATED; @@ -271,8 +270,8 @@ bool s1ap_ctx_mngmt_proc::send_ue_context_release_command(nas* nas_ctx) ecm_ctx_t* ecm_ctx = &nas_ctx->m_ecm_ctx; if (ecm_ctx->state != ECM_STATE_CONNECTED) { - m_s1ap_log->error("UE is not ECM connected. No send context release command. MME UE S1AP Id %d\n", - ecm_ctx->mme_ue_s1ap_id); + m_logger.error("UE is not ECM connected. No send context release command. MME UE S1AP Id %d", + ecm_ctx->mme_ue_s1ap_id); return false; } @@ -290,7 +289,7 @@ bool s1ap_ctx_mngmt_proc::send_ue_context_release_command(nas* nas_ctx) if (active_erabs) { // There are active E-RABs, send release access mearers request srslte::console("There are active E-RABs, send release access bearers request\n"); - m_s1ap_log->info("There are active E-RABs, send release access bearers request\n"); + m_logger.info("There are active E-RABs, send release access bearers request"); // The handle_release_access_bearers_response function will make sure to mark E-RABS DEACTIVATED // It will release the UEs downstream S1-u and keep the upstream S1-U connection active. @@ -318,7 +317,7 @@ bool s1ap_ctx_mngmt_proc::send_ue_context_release_command(nas* nas_ctx) // Send Reply to eNB if (!m_s1ap->s1ap_tx_pdu(tx_pdu, &nas_ctx->m_ecm_ctx.enb_sri)) { - m_s1ap_log->error("Error sending UE Context Release Command.\n"); + m_logger.error("Error sending UE Context Release Command."); return false; } @@ -328,19 +327,19 @@ bool s1ap_ctx_mngmt_proc::send_ue_context_release_command(nas* nas_ctx) bool s1ap_ctx_mngmt_proc::handle_ue_context_release_complete(const asn1::s1ap::ue_context_release_complete_s& rel_comp) { uint32_t mme_ue_s1ap_id = rel_comp.protocol_ies.mme_ue_s1ap_id.value.value; - m_s1ap_log->info("Received UE Context Release Complete. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); + m_logger.info("Received UE Context Release Complete. MME-UE S1AP Id: %d", mme_ue_s1ap_id); srslte::console("Received UE Context Release Complete. MME-UE S1AP Id %d\n", mme_ue_s1ap_id); nas* nas_ctx = m_s1ap->find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == nullptr) { - m_s1ap_log->info("No UE context to release found. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); + m_logger.info("No UE context to release found. MME-UE S1AP Id: %d", mme_ue_s1ap_id); srslte::console("No UE context to release found. MME-UE S1AP Id: %d\n", mme_ue_s1ap_id); return false; } // Delete UE context m_s1ap->release_ue_ecm_ctx(nas_ctx->m_ecm_ctx.mme_ue_s1ap_id); - m_s1ap_log->info("UE Context Release Completed.\n"); + m_logger.info("UE Context Release Completed."); srslte::console("UE Context Release Completed.\n"); return true; } diff --git a/srsepc/src/mme/s1ap_erab_mngmt_proc.cc b/srsepc/src/mme/s1ap_erab_mngmt_proc.cc index 01d282d43..d8db1c1eb 100644 --- a/srsepc/src/mme/s1ap_erab_mngmt_proc.cc +++ b/srsepc/src/mme/s1ap_erab_mngmt_proc.cc @@ -56,7 +56,6 @@ void s1ap_erab_mngmt_proc::cleanup() void s1ap_erab_mngmt_proc::init() { m_s1ap = s1ap::get_instance(); - m_s1ap_log = m_s1ap->m_s1ap_log; m_s1ap_args = m_s1ap->m_s1ap_args; m_pool = srslte::byte_buffer_pool::get_instance(); } @@ -66,7 +65,7 @@ bool s1ap_erab_mngmt_proc::send_erab_release_command(uint32_t enb_ std::vector erabs_to_release, struct sctp_sndrcvinfo enb_sri) { - m_s1ap_log->info("Preparing to send E-RAB Release Command\n"); + m_logger.info("Preparing to send E-RAB Release Command"); // Prepare reply PDU s1ap_pdu_t tx_pdu; @@ -86,11 +85,11 @@ bool s1ap_erab_mngmt_proc::send_erab_release_command(uint32_t enb_ erab_rel_cmd.erab_to_be_released_list.value[i].value.erab_item().cause.set(asn1::s1ap::cause_c::types::misc); erab_rel_cmd.erab_to_be_released_list.value[i].value.erab_item().cause.misc() = asn1::s1ap::cause_misc_opts::unspecified; - m_s1ap_log->info("Sending release comman to %d\n", erabs_to_release[i]); + m_logger.info("Sending release comman to %d", erabs_to_release[i]); } if (!m_s1ap->s1ap_tx_pdu(tx_pdu, &enb_sri)) { - m_s1ap_log->error("Error sending Initial Context Setup Request.\n"); + m_logger.error("Error sending Initial Context Setup Request."); return false; } return true; @@ -102,7 +101,7 @@ bool s1ap_erab_mngmt_proc::send_erab_modify_request(uint32_t srslte::byte_buffer_t* nas_msg, struct sctp_sndrcvinfo enb_sri) { - m_s1ap_log->info("Preparing to send E-RAB Modify Command\n"); + m_logger.info("Preparing to send E-RAB Modify Command"); // Prepare reply PDU s1ap_pdu_t tx_pdu; @@ -132,12 +131,12 @@ bool s1ap_erab_mngmt_proc::send_erab_modify_request(uint32_t asn1::s1ap::pre_emption_vulnerability_opts::not_pre_emptable; erab_to_mod.nas_pdu.resize(nas_msg->N_bytes); memcpy(erab_to_mod.nas_pdu.data(), nas_msg->msg, nas_msg->N_bytes); - m_s1ap_log->info("Sending release comman to E-RAB Id %d\n", erab_it->first); + m_logger.info("Sending release comman to E-RAB Id %d", erab_it->first); i++; } if (!m_s1ap->s1ap_tx_pdu(tx_pdu, &enb_sri)) { - m_s1ap_log->error("Error sending Initial Context Setup Request.\n"); + m_logger.error("Error sending Initial Context Setup Request."); return false; } return true; diff --git a/srsepc/src/mme/s1ap_mngmt_proc.cc b/srsepc/src/mme/s1ap_mngmt_proc.cc index 9738c9a07..79c147f9c 100644 --- a/srsepc/src/mme/s1ap_mngmt_proc.cc +++ b/srsepc/src/mme/s1ap_mngmt_proc.cc @@ -52,7 +52,6 @@ void s1ap_mngmt_proc::cleanup(void) void s1ap_mngmt_proc::init(void) { m_s1ap = s1ap::get_instance(); - m_s1ap_log = m_s1ap->m_s1ap_log; m_s1mme = m_s1ap->get_s1_mme(); m_s1ap_args = m_s1ap->m_s1ap_args; } @@ -61,18 +60,18 @@ bool s1ap_mngmt_proc::handle_s1_setup_request(const asn1::s1ap::s1_setup_request struct sctp_sndrcvinfo* enb_sri) { srslte::console("Received S1 Setup Request.\n"); - m_s1ap_log->info("Received S1 Setup Request.\n"); + m_logger.info("Received S1 Setup Request."); enb_ctx_t enb_ctx = {}; if (!unpack_s1_setup_request(msg, &enb_ctx)) { - m_s1ap_log->error("Malformed S1 Setup Request\n"); + m_logger.error("Malformed S1 Setup Request"); return false; } // Store SCTP sendrecv info memcpy(&enb_ctx.sri, enb_sri, sizeof(struct sctp_sndrcvinfo)); - m_s1ap_log->debug("eNB SCTP association Id: %d\n", enb_sri->sinfo_assoc_id); + m_logger.debug("eNB SCTP association Id: %d", enb_sri->sinfo_assoc_id); // Log S1 Setup Request Info m_s1ap->print_enb_ctx_info(std::string("S1 Setup Request"), enb_ctx); @@ -89,18 +88,18 @@ bool s1ap_mngmt_proc::handle_s1_setup_request(const asn1::s1ap::s1_setup_request // Check matching PLMNs if (enb_ctx.plmn != m_s1ap->get_plmn()) { srslte::console("Sending S1 Setup Failure - Unknown PLMN\n"); - m_s1ap_log->warning("Sending S1 Setup Failure - Unknown PLMN\n"); + m_logger.warning("Sending S1 Setup Failure - Unknown PLMN"); send_s1_setup_failure(asn1::s1ap::cause_misc_opts::unknown_plmn, enb_sri); } else if (!tac_match) { srslte::console("Sending S1 Setup Failure - No matching TAC\n"); - m_s1ap_log->warning("Sending S1 Setup Failure - No matching TAC\n"); + m_logger.warning("Sending S1 Setup Failure - No matching TAC"); send_s1_setup_failure(asn1::s1ap::cause_misc_opts::unspecified, enb_sri); } else { enb_ctx_t* enb_ptr = m_s1ap->find_enb_ctx(enb_ctx.enb_id); if (enb_ptr != nullptr) { // eNB already registered // TODO replace enb_ctx - m_s1ap_log->warning("eNB Already registered\n"); + m_logger.warning("eNB Already registered"); } else { // new eNB m_s1ap->add_new_enb_ctx(enb_ctx, enb_sri); @@ -108,7 +107,7 @@ bool s1ap_mngmt_proc::handle_s1_setup_request(const asn1::s1ap::s1_setup_request send_s1_setup_response(m_s1ap_args, enb_sri); srslte::console("Sending S1 Setup Response\n"); - m_s1ap_log->info("Sending S1 Setup Response\n"); + m_logger.info("Sending S1 Setup Response"); } return true; } @@ -185,7 +184,7 @@ bool s1ap_mngmt_proc::send_s1_setup_failure(asn1::s1ap::cause_misc_opts::options bool s1ap_mngmt_proc::send_s1_setup_response(s1ap_args_t s1ap_args, struct sctp_sndrcvinfo* enb_sri) { - m_s1ap_log->debug("Sending S1 Setup Response\n"); + m_logger.debug("Sending S1 Setup Response"); s1ap_pdu_t tx_pdu; tx_pdu.set_successful_outcome().load_info_obj(ASN1_S1AP_ID_S1_SETUP); @@ -219,9 +218,9 @@ bool s1ap_mngmt_proc::send_s1_setup_response(s1ap_args_t s1ap_args, struct sctp_ s1_resp.relative_mme_capacity.value = 255; if (!m_s1ap->s1ap_tx_pdu(tx_pdu, enb_sri)) { - m_s1ap_log->error("Error sending S1 Setup Response.\n"); + m_logger.error("Error sending S1 Setup Response."); } else { - m_s1ap_log->debug("S1 Setup Response sent\n"); + m_logger.debug("S1 Setup Response sent"); } return true; } diff --git a/srsepc/src/mme/s1ap_nas_transport.cc b/srsepc/src/mme/s1ap_nas_transport.cc index 700214900..d649c1b23 100644 --- a/srsepc/src/mme/s1ap_nas_transport.cc +++ b/srsepc/src/mme/s1ap_nas_transport.cc @@ -56,9 +56,8 @@ void s1ap_nas_transport::cleanup(void) void s1ap_nas_transport::init() { - m_s1ap = s1ap::get_instance(); - m_s1ap_log = m_s1ap->m_s1ap_log; - m_pool = srslte::byte_buffer_pool::get_instance(); + m_s1ap = s1ap::get_instance(); + m_pool = srslte::byte_buffer_pool::get_instance(); // Init NAS args m_nas_init.mcc = m_s1ap->m_s1ap_args.mcc; @@ -94,7 +93,7 @@ bool s1ap_nas_transport::handle_initial_ue_message(const asn1::s1ap::init_ue_msg liblte_mme_parse_msg_header((LIBLTE_BYTE_MSG_STRUCT*)nas_msg, &pd, &msg_type); srslte::console("Initial UE message: %s\n", liblte_nas_msg_type_to_string(msg_type)); - m_s1ap_log->info("Initial UE message: %s\n", liblte_nas_msg_type_to_string(msg_type)); + m_logger.info("Initial UE message: %s", liblte_nas_msg_type_to_string(msg_type)); if (init_ue.protocol_ies.s_tmsi_present) { srslte::uint8_to_uint32(init_ue.protocol_ies.s_tmsi.value.m_tmsi.data(), &m_tmsi); @@ -103,29 +102,26 @@ bool s1ap_nas_transport::handle_initial_ue_message(const asn1::s1ap::init_ue_msg switch (msg_type) { case LIBLTE_MME_MSG_TYPE_ATTACH_REQUEST: srslte::console("Received Initial UE message -- Attach Request\n"); - m_s1ap_log->info("Received Initial UE message -- Attach Request\n"); - err = nas::handle_attach_request(enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if, m_s1ap->m_nas_log); + m_logger.info("Received Initial UE message -- Attach Request"); + err = nas::handle_attach_request(enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if); break; case LIBLTE_MME_SECURITY_HDR_TYPE_SERVICE_REQUEST: srslte::console("Received Initial UE message -- Service Request\n"); - m_s1ap_log->info("Received Initial UE message -- Service Request\n"); - err = nas::handle_service_request( - m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if, m_s1ap->m_nas_log); + m_logger.info("Received Initial UE message -- Service Request"); + err = nas::handle_service_request(m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if); break; case LIBLTE_MME_MSG_TYPE_DETACH_REQUEST: srslte::console("Received Initial UE message -- Detach Request\n"); - m_s1ap_log->info("Received Initial UE message -- Detach Request\n"); - err = - nas::handle_detach_request(m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if, m_s1ap->m_nas_log); + m_logger.info("Received Initial UE message -- Detach Request"); + err = nas::handle_detach_request(m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if); break; case LIBLTE_MME_MSG_TYPE_TRACKING_AREA_UPDATE_REQUEST: srslte::console("Received Initial UE message -- Tracking Area Update Request\n"); - m_s1ap_log->info("Received Initial UE message -- Tracking Area Update Request\n"); - err = nas::handle_tracking_area_update_request( - m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if, m_s1ap->m_nas_log); + m_logger.info("Received Initial UE message -- Tracking Area Update Request"); + err = nas::handle_tracking_area_update_request(m_tmsi, enb_ue_s1ap_id, enb_sri, nas_msg, m_nas_init, m_nas_if); break; default: - m_s1ap_log->info("Unhandled Initial UE Message 0x%x \n", msg_type); + m_logger.info("Unhandled Initial UE Message 0x%x ", msg_type); srslte::console("Unhandled Initial UE Message 0x%x \n", msg_type); err = false; } @@ -145,11 +141,11 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr // Get UE NAS context nas* nas_ctx = m_s1ap->find_nas_ctx_from_mme_ue_s1ap_id(mme_ue_s1ap_id); if (nas_ctx == nullptr) { - m_s1ap_log->warning("Received uplink NAS, but could not find UE NAS context. MME-UE S1AP id: %d\n", mme_ue_s1ap_id); + m_logger.warning("Received uplink NAS, but could not find UE NAS context. MME-UE S1AP id: %d", mme_ue_s1ap_id); return false; } - m_s1ap_log->debug("Received uplink NAS and found UE NAS context. MME-UE S1AP id: %d\n", mme_ue_s1ap_id); + m_logger.debug("Received uplink NAS and found UE NAS context. MME-UE S1AP id: %d", mme_ue_s1ap_id); emm_ctx_t* emm_ctx = &nas_ctx->m_emm_ctx; ecm_ctx_t* ecm_ctx = &nas_ctx->m_ecm_ctx; sec_ctx_t* sec_ctx = &nas_ctx->m_sec_ctx; @@ -169,7 +165,7 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED || sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_WITH_NEW_EPS_SECURITY_CONTEXT || sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED_WITH_NEW_EPS_SECURITY_CONTEXT)) { - m_s1ap_log->error("Unhandled security header type in Uplink NAS Transport: %d\n", sec_hdr_type); + m_logger.error("Unhandled security header type in Uplink NAS Transport: %d", sec_hdr_type); m_pool->deallocate(nas_msg); return false; } @@ -182,18 +178,18 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED_WITH_NEW_EPS_SECURITY_CONTEXT) { mac_valid = nas_ctx->integrity_check(nas_msg); if (mac_valid == false) { - m_s1ap_log->warning("Invalid MAC message. Even if security header indicates integrity protection (Maybe: " - "Identity Response or Authentication Response)\n"); + m_logger.warning("Invalid MAC message. Even if security header indicates integrity protection (Maybe: " + "Identity Response or Authentication Response)"); } } // Decrypt message if indicated if (sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED || sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED_WITH_NEW_EPS_SECURITY_CONTEXT) { - m_s1ap_log->debug_hex(nas_msg->msg, nas_msg->N_bytes, "Encrypted"); + m_logger.debug(nas_msg->msg, nas_msg->N_bytes, "Encrypted"); nas_ctx->cipher_decrypt(nas_msg); msg_encrypted = true; - m_s1ap_log->debug_hex(nas_msg->msg, nas_msg->N_bytes, "Decrypted"); + m_logger.debug(nas_msg->msg, nas_msg->N_bytes, "Decrypted"); } // Now parse message header and handle message @@ -207,8 +203,8 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr // This can happen with integrity protected identity reponse messages if (!(msg_type == LIBLTE_MME_MSG_TYPE_IDENTITY_RESPONSE && sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY)) { - m_s1ap_log->warning( - "Uplink NAS: could not find security context for integrity protected message. MME-UE S1AP id: %d\n", + m_logger.warning( + "Uplink NAS: could not find security context for integrity protected message. MME-UE S1AP id: %d", mme_ue_s1ap_id); m_pool->deallocate(nas_msg); return false; @@ -227,24 +223,24 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr // - DETACH REQUEST; // - DETACH ACCEPT; // - TRACKING AREA UPDATE REQUEST. - m_s1ap_log->info("UL NAS: sec_hdr_type: %s, mac_vaild: %s, msg_encrypted: %s\n", - liblte_nas_sec_hdr_type_to_string(sec_hdr_type), - mac_valid == true ? "yes" : "no", - msg_encrypted == true ? "yes" : "no"); + m_logger.info("UL NAS: sec_hdr_type: %s, mac_vaild: %s, msg_encrypted: %s", + liblte_nas_sec_hdr_type_to_string(sec_hdr_type), + mac_valid == true ? "yes" : "no", + msg_encrypted == true ? "yes" : "no"); switch (msg_type) { case LIBLTE_MME_MSG_TYPE_ATTACH_REQUEST: - m_s1ap_log->info("UL NAS: Attach Request\n"); + m_logger.info("UL NAS: Attach Request"); srslte::console("UL NAS: Attach Resquest\n"); nas_ctx->handle_attach_request(nas_msg); break; case LIBLTE_MME_MSG_TYPE_IDENTITY_RESPONSE: - m_s1ap_log->info("UL NAS: Received Identity Response\n"); + m_logger.info("UL NAS: Received Identity Response"); srslte::console("UL NAS: Received Identity Response\n"); nas_ctx->handle_identity_response(nas_msg); break; case LIBLTE_MME_MSG_TYPE_AUTHENTICATION_RESPONSE: - m_s1ap_log->info("UL NAS: Received Authentication Response\n"); + m_logger.info("UL NAS: Received Authentication Response"); srslte::console("UL NAS: Received Authentication Response\n"); nas_ctx->handle_authentication_response(nas_msg); // In case of a successful authentication response, security mode command follows. @@ -255,19 +251,19 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr break; // Authentication failure with the option sync failure can be sent not integrity protected case LIBLTE_MME_MSG_TYPE_AUTHENTICATION_FAILURE: - m_s1ap_log->info("UL NAS: Authentication Failure\n"); + m_logger.info("UL NAS: Authentication Failure"); srslte::console("UL NAS: Authentication Failure\n"); nas_ctx->handle_authentication_failure(nas_msg); break; // Detach request can be sent not integrity protected when "power off" option is used case LIBLTE_MME_MSG_TYPE_DETACH_REQUEST: - m_s1ap_log->info("UL NAS: Detach Request\n"); + m_logger.info("UL NAS: Detach Request"); srslte::console("UL NAS: Detach Request\n"); // TODO: check integrity protection in detach request nas_ctx->handle_detach_request(nas_msg); break; case LIBLTE_MME_MSG_TYPE_SECURITY_MODE_COMPLETE: - m_s1ap_log->info("UL NAS: Received Security Mode Complete\n"); + m_logger.info("UL NAS: Received Security Mode Complete"); srslte::console("UL NAS: Received Security Mode Complete\n"); if (sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED_WITH_NEW_EPS_SECURITY_CONTEXT && mac_valid == true) { @@ -275,45 +271,45 @@ bool s1ap_nas_transport::handle_uplink_nas_transport(const asn1::s1ap::ul_nas_tr } else { // Security Mode Complete was not integrity protected srslte::console("Security Mode Complete %s. Discard message.\n", - (mac_valid ? "not integrity protected" : "invalid integrity")); - m_s1ap_log->warning("Security Mode Complete %s. Discard message.\n", - (mac_valid ? "not integrity protected" : "invalid integrity")); + (mac_valid ? "not integrity protected" : "invalid integrity")); + m_logger.warning("Security Mode Complete %s. Discard message.", + (mac_valid ? "not integrity protected" : "invalid integrity")); increase_ul_nas_cnt = false; } break; case LIBLTE_MME_MSG_TYPE_ATTACH_COMPLETE: - m_s1ap_log->info("UL NAS: Received Attach Complete\n"); + m_logger.info("UL NAS: Received Attach Complete"); srslte::console("UL NAS: Received Attach Complete\n"); if (sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED && mac_valid == true) { nas_ctx->handle_attach_complete(nas_msg); } else { // Attach Complete was not integrity protected srslte::console("Attach Complete not integrity protected. Discard message.\n"); - m_s1ap_log->warning("Attach Complete not integrity protected. Discard message.\n"); + m_logger.warning("Attach Complete not integrity protected. Discard message."); increase_ul_nas_cnt = false; } break; case LIBLTE_MME_MSG_TYPE_ESM_INFORMATION_RESPONSE: - m_s1ap_log->info("UL NAS: Received ESM Information Response\n"); + m_logger.info("UL NAS: Received ESM Information Response"); srslte::console("UL NAS: Received ESM Information Response\n"); if (sec_hdr_type == LIBLTE_MME_SECURITY_HDR_TYPE_INTEGRITY_AND_CIPHERED && mac_valid == true) { nas_ctx->handle_esm_information_response(nas_msg); } else { // Attach Complete was not integrity protected srslte::console("ESM Information Response %s. Discard message.\n", - (mac_valid ? "not integrity protected" : "invalid integrity")); - m_s1ap_log->warning("ESM Information Response %s. Discard message.\n", - (mac_valid ? "not integrity protected" : "invalid integrity")); + (mac_valid ? "not integrity protected" : "invalid integrity")); + m_logger.warning("ESM Information Response %s. Discard message.", + (mac_valid ? "not integrity protected" : "invalid integrity")); increase_ul_nas_cnt = false; } break; case LIBLTE_MME_MSG_TYPE_TRACKING_AREA_UPDATE_REQUEST: - m_s1ap_log->info("UL NAS: Tracking Area Update Request\n"); + m_logger.info("UL NAS: Tracking Area Update Request"); srslte::console("UL NAS: Tracking Area Update Request\n"); nas_ctx->handle_tracking_area_update_request(nas_msg); break; default: - m_s1ap_log->warning("Unhandled NAS integrity protected message %s\n", liblte_nas_msg_type_to_string(msg_type)); + m_logger.warning("Unhandled NAS integrity protected message %s", liblte_nas_msg_type_to_string(msg_type)); srslte::console("Unhandled NAS integrity protected message %s\n", liblte_nas_msg_type_to_string(msg_type)); m_pool->deallocate(nas_msg); return false; @@ -333,10 +329,10 @@ bool s1ap_nas_transport::send_downlink_nas_transport(uint32_t enb_ srslte::byte_buffer_t* nas_msg, struct sctp_sndrcvinfo enb_sri) { - m_s1ap_log->debug("Sending message to eNB with SCTP association %d. MME UE S1AP ID %d, eNB UE S1AP ID %d\n", - enb_sri.sinfo_assoc_id, - mme_ue_s1ap_id, - enb_ue_s1ap_id); + m_logger.debug("Sending message to eNB with SCTP association %d. MME UE S1AP ID %d, eNB UE S1AP ID %d", + enb_sri.sinfo_assoc_id, + mme_ue_s1ap_id, + enb_ue_s1ap_id); // Setup initiating message s1ap_pdu_t tx_pdu; diff --git a/srsepc/src/mme/s1ap_paging.cc b/srsepc/src/mme/s1ap_paging.cc index 417bd87ea..c4b17b1dc 100644 --- a/srsepc/src/mme/s1ap_paging.cc +++ b/srsepc/src/mme/s1ap_paging.cc @@ -28,14 +28,13 @@ void s1ap_paging::init() { m_s1ap = s1ap::get_instance(); m_mme = mme::get_instance(); - m_s1ap_log = m_s1ap->m_s1ap_log; m_s1ap_args = m_s1ap->m_s1ap_args; m_pool = srslte::byte_buffer_pool::get_instance(); } bool s1ap_paging::send_paging(uint64_t imsi, uint16_t erab_to_setup) { - m_s1ap_log->info("Preparing to Page UE -- IMSI %015" PRIu64 "\n", imsi); + m_logger.info("Preparing to Page UE -- IMSI %015" PRIu64 "", imsi); // Prepare reply PDU s1ap_pdu_t tx_pdu; @@ -45,7 +44,7 @@ bool s1ap_paging::send_paging(uint64_t imsi, uint16_t erab_to_setup) // Getting UE NAS Context nas* nas_ctx = m_s1ap->find_nas_ctx_from_imsi(imsi); if (nas_ctx == nullptr) { - m_s1ap_log->error("Could not find UE to page NAS context\n"); + m_logger.error("Could not find UE to page NAS context"); return false; } @@ -73,7 +72,7 @@ bool s1ap_paging::send_paging(uint64_t imsi, uint16_t erab_to_setup) // Start T3413 if (!nas_ctx->start_timer(T_3413)) { - m_s1ap_log->error("Could not start T3413 -- Aborting paging\n"); + m_logger.error("Could not start T3413 -- Aborting paging"); // TODO Send data notification failure to SPGW return false; } @@ -82,7 +81,7 @@ bool s1ap_paging::send_paging(uint64_t imsi, uint16_t erab_to_setup) it++) { enb_ctx_t* enb_ctx = it->second; if (!m_s1ap->s1ap_tx_pdu(tx_pdu, &enb_ctx->sri)) { - m_s1ap_log->error("Error paging to eNB. eNB Id: 0x%x.\n", enb_ctx->enb_id); + m_logger.error("Error paging to eNB. eNB Id: 0x%x.", enb_ctx->enb_id); return false; } } diff --git a/srsepc/src/spgw/gtpc.cc b/srsepc/src/spgw/gtpc.cc index 124377e4f..520bad6e7 100644 --- a/srsepc/src/spgw/gtpc.cc +++ b/srsepc/src/spgw/gtpc.cc @@ -45,15 +45,11 @@ spgw::gtpc::~gtpc() int spgw::gtpc::init(spgw_args_t* args, spgw* spgw, gtpu_interface_gtpc* gtpu, - srslte::log_filter* gtpc_log, const std::map& ip_to_imsi) { int err; m_pool = srslte::byte_buffer_pool::get_instance(); - // Init log - m_gtpc_log = gtpc_log; - // Init interfaces m_spgw = spgw; m_gtpu = gtpu; @@ -75,7 +71,7 @@ int spgw::gtpc::init(spgw_args_t* args, // Limit paging queue m_max_paging_queue = args->max_paging_queue; - m_gtpc_log->info("SPGW S11 Initialized.\n"); + m_logger.info("SPGW S11 Initialized."); srslte::console("SPGW S11 Initialized.\n"); return 0; } @@ -84,7 +80,7 @@ void spgw::gtpc::stop() { std::map::iterator it = m_teid_to_tunnel_ctx.begin(); while (it != m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->info("Deleting SP-GW GTP-C Tunnel. IMSI: %015" PRIu64 "\n", it->second->imsi); + m_logger.info("Deleting SP-GW GTP-C Tunnel. IMSI: %015" PRIu64 "", it->second->imsi); srslte::console("Deleting SP-GW GTP-C Tunnel. IMSI: %015" PRIu64 "\n", it->second->imsi); delete it->second; m_teid_to_tunnel_ctx.erase(it++); @@ -99,12 +95,12 @@ int spgw::gtpc::init_s11(spgw_args_t* args) char mme_addr_name[] = "@mme_s11"; // Logs - m_gtpc_log->info("Initializing SPGW S11 interface.\n"); + m_logger.info("Initializing SPGW S11 interface."); // Open Socket m_s11 = socket(AF_UNIX, SOCK_DGRAM, 0); if (m_s11 < 0) { - m_gtpc_log->error("Error opening UNIX socket. Error %s\n", strerror(errno)); + m_logger.error("Error opening UNIX socket. Error %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } @@ -122,7 +118,7 @@ int spgw::gtpc::init_s11(spgw_args_t* args) // Bind socket to address if (bind(m_s11, (const struct sockaddr*)&m_spgw_addr, sizeof(m_spgw_addr)) == -1) { - m_gtpc_log->error("Error binding UNIX socket. Error %s\n", strerror(errno)); + m_logger.error("Error binding UNIX socket. Error %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } return SRSLTE_SUCCESS; @@ -130,16 +126,16 @@ int spgw::gtpc::init_s11(spgw_args_t* args) bool spgw::gtpc::send_s11_pdu(const srslte::gtpc_pdu& pdu) { - m_gtpc_log->debug("SPGW Sending S11 PDU! N_Bytes: %zd\n", sizeof(pdu)); + m_logger.debug("SPGW Sending S11 PDU! N_Bytes: %zd", sizeof(pdu)); // TODO add serialization code here // Send S11 message to MME int n = sendto(m_s11, &pdu, sizeof(pdu), 0, (const sockaddr*)&m_mme_addr, sizeof(m_mme_addr)); if (n < 0) { - m_gtpc_log->error("Error sending to socket. Error %s", strerror(errno)); + m_logger.error("Error sending to socket. Error %s", strerror(errno)); return false; } else { - m_gtpc_log->debug("SPGW S11 Sent %d Bytes.\n", n); + m_logger.debug("SPGW S11 Sent %d Bytes.", n); } return true; } @@ -149,7 +145,7 @@ void spgw::gtpc::handle_s11_pdu(srslte::byte_buffer_t* msg) // TODO add deserialization code here srslte::gtpc_pdu* pdu = (srslte::gtpc_pdu*)msg->msg; srslte::console("Received GTP-C PDU. Message type: %s\n", srslte::gtpc_msg_type_to_str(pdu->header.type)); - m_gtpc_log->debug("Received GTP-C PDU. Message type: %s\n", srslte::gtpc_msg_type_to_str(pdu->header.type)); + m_logger.debug("Received GTP-C PDU. Message type: %s", srslte::gtpc_msg_type_to_str(pdu->header.type)); switch (pdu->header.type) { case srslte::GTPC_MSG_TYPE_CREATE_SESSION_REQUEST: handle_create_session_request(pdu->choice.create_session_request); @@ -171,14 +167,14 @@ void spgw::gtpc::handle_s11_pdu(srslte::byte_buffer_t* msg) pdu->choice.downlink_data_notification_failure_indication); break; default: - m_gtpc_log->error("Unhandled GTP-C message type\n"); + m_logger.error("Unhandled GTP-C message type"); } return; } void spgw::gtpc::handle_create_session_request(const struct srslte::gtpc_create_session_request& cs_req) { - m_gtpc_log->info("SPGW Received Create Session Request\n"); + m_logger.info("SPGW Received Create Session Request"); spgw_tunnel_ctx_t* tunnel_ctx; int default_bearer_id = 5; // Check if IMSI has active GTP-C and/or GTP-U @@ -189,7 +185,7 @@ void spgw::gtpc::handle_create_session_request(const struct srslte::gtpc_create_ srslte::console("SPGW: Deleted previous context.\n"); } - m_gtpc_log->info("Creating new GTP-C context\n"); + m_logger.info("Creating new GTP-C context"); tunnel_ctx = create_gtpc_ctx(cs_req); // Create session response message @@ -223,7 +219,7 @@ void spgw::gtpc::handle_create_session_request(const struct srslte::gtpc_create_ cs_resp->paa.pdn_type = srslte::GTPC_PDN_TYPE_IPV4; cs_resp->paa.ipv4_present = true; cs_resp->paa.ipv4 = tunnel_ctx->ue_ipv4; - m_gtpc_log->info("Sending Create Session Response\n"); + m_logger.info("Sending Create Session Response"); // Send Create session response to MME send_s11_pdu(cs_resp_pdu); @@ -233,13 +229,13 @@ void spgw::gtpc::handle_create_session_request(const struct srslte::gtpc_create_ void spgw::gtpc::handle_modify_bearer_request(const struct srslte::gtpc_header& mb_req_hdr, const struct srslte::gtpc_modify_bearer_request& mb_req) { - m_gtpc_log->info("Received Modified Bearer Request\n"); + m_logger.info("Received Modified Bearer Request"); // Get control tunnel info from mb_req PDU uint32_t ctrl_teid = mb_req_hdr.teid; std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(ctrl_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID %d to modify\n", ctrl_teid); + m_logger.warning("Could not find TEID %d to modify", ctrl_teid); return; } spgw_tunnel_ctx_t* tunnel_ctx = tunnel_it->second; @@ -248,22 +244,21 @@ void spgw::gtpc::handle_modify_bearer_request(const struct srslte::gtpc_header& tunnel_ctx->dw_user_fteid.teid = mb_req.eps_bearer_context_to_modify.s1_u_enb_f_teid.teid; tunnel_ctx->dw_user_fteid.ipv4 = mb_req.eps_bearer_context_to_modify.s1_u_enb_f_teid.ipv4; // Set up actual tunnel - m_gtpc_log->info("Setting Up GTP-U tunnel. Tunnel info: \n"); + m_logger.info("Setting Up GTP-U tunnel. Tunnel info: "); struct in_addr addr; addr.s_addr = tunnel_ctx->ue_ipv4; - m_gtpc_log->info("IMSI: %015" PRIu64 ", UE IP: %s \n", tunnel_ctx->imsi, inet_ntoa(addr)); - m_gtpc_log->info("S-GW Rx Ctrl TEID 0x%x, MME Rx Ctrl TEID 0x%x\n", - tunnel_ctx->up_ctrl_fteid.teid, - tunnel_ctx->dw_ctrl_fteid.teid); - m_gtpc_log->info("S-GW Rx Ctrl IP (NA), MME Rx Ctrl IP (NA)\n"); + m_logger.info("IMSI: %015" PRIu64 ", UE IP: %s ", tunnel_ctx->imsi, inet_ntoa(addr)); + m_logger.info( + "S-GW Rx Ctrl TEID 0x%x, MME Rx Ctrl TEID 0x%x", tunnel_ctx->up_ctrl_fteid.teid, tunnel_ctx->dw_ctrl_fteid.teid); + m_logger.info("S-GW Rx Ctrl IP (NA), MME Rx Ctrl IP (NA)"); struct in_addr addr2; addr2.s_addr = tunnel_ctx->up_user_fteid.ipv4; - m_gtpc_log->info("S-GW Rx User TEID 0x%x, S-GW Rx User IP %s\n", tunnel_ctx->up_user_fteid.teid, inet_ntoa(addr2)); + m_logger.info("S-GW Rx User TEID 0x%x, S-GW Rx User IP %s", tunnel_ctx->up_user_fteid.teid, inet_ntoa(addr2)); struct in_addr addr3; addr3.s_addr = tunnel_ctx->dw_user_fteid.ipv4; - m_gtpc_log->info("eNB Rx User TEID 0x%x, eNB Rx User IP %s\n", tunnel_ctx->dw_user_fteid.teid, inet_ntoa(addr3)); + m_logger.info("eNB Rx User TEID 0x%x, eNB Rx User IP %s", tunnel_ctx->dw_user_fteid.teid, inet_ntoa(addr3)); // Setup IP to F-TEID map m_gtpu->modify_gtpu_tunnel(tunnel_ctx->ue_ipv4, tunnel_ctx->dw_user_fteid, tunnel_ctx->up_ctrl_fteid.teid); @@ -271,7 +266,7 @@ void spgw::gtpc::handle_modify_bearer_request(const struct srslte::gtpc_header& // Mark paging as done & send queued packets if (tunnel_ctx->paging_pending == true) { tunnel_ctx->paging_pending = false; - m_gtpc_log->debug("Modify Bearer Request received after Downling Data Notification was sent\n"); + m_logger.debug("Modify Bearer Request received after Downling Data Notification was sent"); srslte::console("Modify Bearer Request received after Downling Data Notification was sent\n"); m_gtpu->send_all_queued_packets(tunnel_ctx->dw_user_fteid, tunnel_ctx->paging_queue); } @@ -303,7 +298,7 @@ void spgw::gtpc::handle_delete_session_request(const srslte::gtpc_header& uint32_t ctrl_teid = header.teid; std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(ctrl_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID 0x%x to delete session\n", ctrl_teid); + m_logger.warning("Could not find TEID 0x%x to delete session", ctrl_teid); return; } spgw_tunnel_ctx_t* tunnel_ctx = tunnel_it->second; @@ -320,7 +315,7 @@ void spgw::gtpc::handle_release_access_bearers_request(const srslte::gtpc_header uint32_t ctrl_teid = header.teid; std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(ctrl_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID 0x%x to release bearers\n", ctrl_teid); + m_logger.warning("Could not find TEID 0x%x to release bearers", ctrl_teid); return; } spgw_tunnel_ctx_t* tunnel_ctx = tunnel_it->second; @@ -333,7 +328,7 @@ void spgw::gtpc::handle_release_access_bearers_request(const srslte::gtpc_header bool spgw::gtpc::send_downlink_data_notification(uint32_t spgw_ctr_teid) { - m_gtpc_log->debug("Sending Downlink Notification Request\n"); + m_logger.debug("Sending Downlink Notification Request"); struct srslte::gtpc_pdu dl_not_pdu; std::memset(&dl_not_pdu, 0, sizeof(dl_not_pdu)); @@ -343,14 +338,14 @@ bool spgw::gtpc::send_downlink_data_notification(uint32_t spgw_ctr_teid) // Find MME Ctrl TEID std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(spgw_ctr_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID 0x%x to send downlink notification.\n", spgw_ctr_teid); + m_logger.warning("Could not find TEID 0x%x to send downlink notification.", spgw_ctr_teid); return false; } spgw_tunnel_ctx_t* tunnel_ctx = tunnel_it->second; // Check if there is no Paging already pending. if (tunnel_ctx->paging_pending == true) { - m_gtpc_log->debug("UE Downlink Data Notification still pending.\n"); + m_logger.debug("UE Downlink Data Notification still pending."); return false; } @@ -376,13 +371,13 @@ void spgw::gtpc::handle_downlink_data_notification_acknowledge( const srslte::gtpc_header& header, const srslte::gtpc_downlink_data_notification_acknowledge& not_ack) { - m_gtpc_log->debug("Handling downlink data notification acknowledge\n"); + m_logger.debug("Handling downlink data notification acknowledge"); // Find tunel ctxt uint32_t ctrl_teid = header.teid; std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(ctrl_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID 0x%x to handle notification acknowldge\n", ctrl_teid); + m_logger.warning("Could not find TEID 0x%x to handle notification acknowldge", ctrl_teid); return; } spgw_tunnel_ctx_t* tunnel_ctx = tunnel_it->second; @@ -390,11 +385,11 @@ void spgw::gtpc::handle_downlink_data_notification_acknowledge( not_ack.cause.cause_value == srslte::GTPC_CAUSE_VALUE_UE_ALREADY_RE_ATTACHED || not_ack.cause.cause_value == srslte::GTPC_CAUSE_VALUE_UNABLE_TO_PAGE_UE || not_ack.cause.cause_value == srslte::GTPC_CAUSE_VALUE_UNABLE_TO_PAGE_UE_DUE_TO_SUSPENSION) { - m_gtpc_log->warning("Downlink Data Notification Acknowledge indicates failure.\n"); + m_logger.warning("Downlink Data Notification Acknowledge indicates failure."); free_all_queued_packets(tunnel_ctx); tunnel_ctx->paging_pending = false; } else if (not_ack.cause.cause_value != srslte::GTPC_CAUSE_VALUE_REQUEST_ACCEPTED) { - m_gtpc_log->warning("Invalid cause in Downlink Data Notification Acknowledge.\n"); + m_logger.warning("Invalid cause in Downlink Data Notification Acknowledge."); free_all_queued_packets(tunnel_ctx); tunnel_ctx->paging_pending = false; } @@ -405,12 +400,12 @@ void spgw::gtpc::handle_downlink_data_notification_failure_indication( const srslte::gtpc_header& header, const srslte::gtpc_downlink_data_notification_failure_indication& not_fail) { - m_gtpc_log->debug("Handling downlink data notification failure indication\n"); + m_logger.debug("Handling downlink data notification failure indication"); // Find tunel ctxt uint32_t ctrl_teid = header.teid; std::map::iterator tunnel_it = m_teid_to_tunnel_ctx.find(ctrl_teid); if (tunnel_it == m_teid_to_tunnel_ctx.end()) { - m_gtpc_log->warning("Could not find TEID 0x%x to handle notification failure indication\n", ctrl_teid); + m_logger.warning("Could not find TEID 0x%x to handle notification failure indication", ctrl_teid); return; } @@ -418,10 +413,9 @@ void spgw::gtpc::handle_downlink_data_notification_failure_indication( if (not_fail.cause.cause_value == srslte::GTPC_CAUSE_VALUE_UE_NOT_RESPONDING || not_fail.cause.cause_value == srslte::GTPC_CAUSE_VALUE_SERVICE_DENIED || not_fail.cause.cause_value == srslte::GTPC_CAUSE_VALUE_UE_ALREADY_RE_ATTACHED) { - m_gtpc_log->debug("Downlink Data Notification failure indication cause: %d.\n", not_fail.cause.cause_value); + m_logger.debug("Downlink Data Notification failure indication cause: %d.", not_fail.cause.cause_value); } else { - m_gtpc_log->warning("Invalid cause in Downlink Data Notification Failure Indication %d\n", - not_fail.cause.cause_value); + m_logger.warning("Invalid cause in Downlink Data Notification Failure Indication %d", not_fail.cause.cause_value); } free_all_queued_packets(tunnel_ctx); tunnel_ctx->paging_pending = false; @@ -471,7 +465,7 @@ bool spgw::gtpc::delete_gtpc_ctx(uint32_t ctrl_teid) { spgw_tunnel_ctx_t* tunnel_ctx; if (!m_teid_to_tunnel_ctx.count(ctrl_teid)) { - m_gtpc_log->error("Could not find GTP context to delete.\n"); + m_logger.error("Could not find GTP context to delete."); return false; } tunnel_ctx = m_teid_to_tunnel_ctx[ctrl_teid]; @@ -495,23 +489,22 @@ bool spgw::gtpc::queue_downlink_packet(uint32_t ctrl_teid, srslte::byte_buffer_t { spgw_tunnel_ctx_t* tunnel_ctx; if (!m_teid_to_tunnel_ctx.count(ctrl_teid)) { - m_gtpc_log->error("Could not find GTP context to queue.\n"); + m_logger.error("Could not find GTP context to queue."); goto pkt_discard; } tunnel_ctx = m_teid_to_tunnel_ctx[ctrl_teid]; if (!tunnel_ctx->paging_pending) { - m_gtpc_log->error("Paging not pending. Not queueing packet\n"); + m_logger.error("Paging not pending. Not queueing packet"); goto pkt_discard; } if (tunnel_ctx->paging_queue.size() < m_max_paging_queue) { tunnel_ctx->paging_queue.push(msg); - m_gtpc_log->debug( - "Queued packet. IMSI %" PRIu64 ", Packets in Queue %zd\n", tunnel_ctx->imsi, tunnel_ctx->paging_queue.size()); + m_logger.debug( + "Queued packet. IMSI %" PRIu64 ", Packets in Queue %zd", tunnel_ctx->imsi, tunnel_ctx->paging_queue.size()); } else { - m_gtpc_log->debug("Paging queue full. IMSI %" PRIu64 ", Packets in Queue %zd\n", - tunnel_ctx->imsi, - tunnel_ctx->paging_queue.size()); + m_logger.debug( + "Paging queue full. IMSI %" PRIu64 ", Packets in Queue %zd", tunnel_ctx->imsi, tunnel_ctx->paging_queue.size()); goto pkt_discard; } return true; @@ -524,12 +517,12 @@ pkt_discard: bool spgw::gtpc::free_all_queued_packets(spgw_tunnel_ctx_t* tunnel_ctx) { if (!tunnel_ctx->paging_pending) { - m_gtpc_log->warning("Freeing queue with paging not pending.\n"); + m_logger.warning("Freeing queue with paging not pending."); } while (!tunnel_ctx->paging_queue.empty()) { srslte::byte_buffer_t* pkt = tunnel_ctx->paging_queue.front(); - m_gtpc_log->debug("Dropping packet. Bytes %d\n", pkt->N_bytes); + m_logger.debug("Dropping packet. Bytes %d", pkt->N_bytes); m_pool->deallocate(pkt); tunnel_ctx->paging_queue.pop(); } @@ -542,9 +535,9 @@ int spgw::gtpc::init_ue_ip(spgw_args_t* args, const std::maperror("SPGW: static ip addr %s for imsi %015" PRIu64 ", is reserved for the epc tun interface\n", - iter->first.c_str(), - iter->second); + m_logger.error("SPGW: static ip addr %s for imsi %015" PRIu64 ", is reserved for the epc tun interface", + iter->first.c_str(), + iter->second); return SRSLTE_ERROR_OUT_OF_BOUNDS; } @@ -553,8 +546,8 @@ int spgw::gtpc::init_ue_ip(spgw_args_t* args, const std::mapfirst.c_str()); if (!m_imsi_to_ip.insert(std::make_pair(iter->second, in_addr)).second) { - m_gtpc_log->error( - "SPGW: duplicate imsi %015" PRIu64 " for static ip address %s.\n", iter->second, iter->first.c_str()); + m_logger.error( + "SPGW: duplicate imsi %015" PRIu64 " for static ip address %s.", iter->second, iter->first.c_str()); return SRSLTE_ERROR_OUT_OF_BOUNDS; } } @@ -567,12 +560,12 @@ int spgw::gtpc::init_ue_ip(spgw_args_t* args, const std::map::const_iterator iter = ip_to_imsi.find(inet_ntoa(ue_addr)); if (iter != ip_to_imsi.end()) { - m_gtpc_log->debug("SPGW: init_ue_ip ue ip addr %s is reserved for imsi %015" PRIu64 ", not adding to pool\n", - iter->first.c_str(), - iter->second); + m_logger.debug("SPGW: init_ue_ip ue ip addr %s is reserved for imsi %015" PRIu64 ", not adding to pool", + iter->first.c_str(), + iter->second); } else { m_ue_ip_addr_pool.insert(ue_addr.s_addr); - m_gtpc_log->debug("SPGW: init_ue_ip ue ip addr %s is added to pool\n", inet_ntoa(ue_addr)); + m_logger.debug("SPGW: init_ue_ip ue ip addr %s is added to pool", inet_ntoa(ue_addr)); } } return SRSLTE_SUCCESS; @@ -585,15 +578,15 @@ in_addr_t spgw::gtpc::get_new_ue_ipv4(uint64_t imsi) std::map::const_iterator iter = m_imsi_to_ip.find(imsi); if (iter != m_imsi_to_ip.end()) { ue_addr = iter->second; - m_gtpc_log->info("SPGW: get_new_ue_ipv4 static ip addr %s\n", inet_ntoa(ue_addr)); + m_logger.info("SPGW: get_new_ue_ipv4 static ip addr %s", inet_ntoa(ue_addr)); } else { if (m_ue_ip_addr_pool.empty()) { - m_gtpc_log->error("SPGW: ue address pool is empty\n"); + m_logger.error("SPGW: ue address pool is empty"); ue_addr.s_addr = 0; } else { ue_addr.s_addr = *m_ue_ip_addr_pool.begin(); m_ue_ip_addr_pool.erase(ue_addr.s_addr); - m_gtpc_log->info("SPGW: get_new_ue_ipv4 pool ip addr %s\n", inet_ntoa(ue_addr)); + m_logger.info("SPGW: get_new_ue_ipv4 pool ip addr %s", inet_ntoa(ue_addr)); } } return ue_addr.s_addr; diff --git a/srsepc/src/spgw/gtpu.cc b/srsepc/src/spgw/gtpu.cc index cd6b19e8b..8e2f1faf7 100644 --- a/srsepc/src/spgw/gtpu.cc +++ b/srsepc/src/spgw/gtpu.cc @@ -69,7 +69,7 @@ int spgw::gtpu::init(spgw_args_t* args, spgw* spgw, gtpc_interface_gtpu* gtpc, s return err; } - m_gtpu_log->info("SPGW GTP-U Initialized.\n"); + m_logger.info("SPGW GTP-U Initialized."); srslte::console("SPGW GTP-U Initialized.\n"); return SRSLTE_SUCCESS; } @@ -97,9 +97,9 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) // Construct the TUN device m_sgi = open("/dev/net/tun", O_RDWR); - m_gtpu_log->info("TUN file descriptor = %d\n", m_sgi); + m_logger.info("TUN file descriptor = %d", m_sgi); if (m_sgi < 0) { - m_gtpu_log->error("Failed to open TUN device: %s\n", strerror(errno)); + m_logger.error("Failed to open TUN device: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } @@ -110,7 +110,7 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) ifr.ifr_ifrn.ifrn_name[IFNAMSIZ - 1] = '\0'; if (ioctl(m_sgi, TUNSETIFF, &ifr) < 0) { - m_gtpu_log->error("Failed to set TUN device name: %s\n", strerror(errno)); + m_logger.error("Failed to set TUN device name: %s", strerror(errno)); close(m_sgi); return SRSLTE_ERROR_CANT_START; } @@ -118,7 +118,7 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) // Bring up the interface sgi_sock = socket(AF_INET, SOCK_DGRAM, 0); if (ioctl(sgi_sock, SIOCGIFFLAGS, &ifr) < 0) { - m_gtpu_log->error("Failed to bring up socket: %s\n", strerror(errno)); + m_logger.error("Failed to bring up socket: %s", strerror(errno)); close(sgi_sock); close(m_sgi); return SRSLTE_ERROR_CANT_START; @@ -126,7 +126,7 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) ifr.ifr_flags |= IFF_UP | IFF_RUNNING; if (ioctl(sgi_sock, SIOCSIFFLAGS, &ifr) < 0) { - m_gtpu_log->error("Failed to set socket flags: %s\n", strerror(errno)); + m_logger.error("Failed to set socket flags: %s", strerror(errno)); close(sgi_sock); close(m_sgi); return SRSLTE_ERROR_CANT_START; @@ -139,8 +139,8 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) addr->sin_port = 0; if (ioctl(sgi_sock, SIOCSIFADDR, &ifr) < 0) { - m_gtpu_log->error( - "Failed to set TUN interface IP. Address: %s, Error: %s\n", args->sgi_if_addr.c_str(), strerror(errno)); + m_logger.error( + "Failed to set TUN interface IP. Address: %s, Error: %s", args->sgi_if_addr.c_str(), strerror(errno)); close(m_sgi); close(sgi_sock); return SRSLTE_ERROR_CANT_START; @@ -149,7 +149,7 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) ifr.ifr_netmask.sa_family = AF_INET; ((struct sockaddr_in*)&ifr.ifr_netmask)->sin_addr.s_addr = inet_addr("255.255.255.0"); if (ioctl(sgi_sock, SIOCSIFNETMASK, &ifr) < 0) { - m_gtpu_log->error("Failed to set TUN interface Netmask. Error: %s\n", strerror(errno)); + m_logger.error("Failed to set TUN interface Netmask. Error: %s", strerror(errno)); close(m_sgi); close(sgi_sock); return SRSLTE_ERROR_CANT_START; @@ -157,7 +157,7 @@ int spgw::gtpu::init_sgi(spgw_args_t* args) close(sgi_sock); m_sgi_up = true; - m_gtpu_log->info("Initialized SGi interface\n"); + m_logger.info("Initialized SGi interface"); return SRSLTE_SUCCESS; } @@ -166,7 +166,7 @@ int spgw::gtpu::init_s1u(spgw_args_t* args) // Open S1-U socket m_s1u = socket(AF_INET, SOCK_DGRAM, 0); if (m_s1u == -1) { - m_gtpu_log->error("Failed to open socket: %s\n", strerror(errno)); + m_logger.error("Failed to open socket: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } m_s1u_up = true; @@ -177,13 +177,13 @@ int spgw::gtpu::init_s1u(spgw_args_t* args) m_s1u_addr.sin_port = htons(GTPU_RX_PORT); if (bind(m_s1u, (struct sockaddr*)&m_s1u_addr, sizeof(struct sockaddr_in))) { - m_gtpu_log->error("Failed to bind socket: %s\n", strerror(errno)); + m_logger.error("Failed to bind socket: %s", strerror(errno)); return SRSLTE_ERROR_CANT_START; } - m_gtpu_log->info("S1-U socket = %d\n", m_s1u); - m_gtpu_log->info("S1-U IP = %s, Port = %d \n", inet_ntoa(m_s1u_addr.sin_addr), ntohs(m_s1u_addr.sin_port)); + m_logger.info("S1-U socket = %d", m_s1u); + m_logger.info("S1-U IP = %s, Port = %d ", inet_ntoa(m_s1u_addr.sin_addr), ntohs(m_s1u_addr.sin_port)); - m_gtpu_log->info("Initialized S1-U interface\n"); + m_logger.info("Initialized S1-U interface"); return SRSLTE_SUCCESS; } @@ -197,21 +197,21 @@ void spgw::gtpu::handle_sgi_pdu(srslte::byte_buffer_t* msg) srslte::gtpc_f_teid_ie enb_fteid; uint32_t spgw_teid; struct iphdr* iph = (struct iphdr*)msg->msg; - m_gtpu_log->debug("Received SGi PDU. Bytes %d\n", msg->N_bytes); + m_logger.debug("Received SGi PDU. Bytes %d", msg->N_bytes); if (iph->version != 4) { - m_gtpu_log->info("IPv6 not supported yet.\n"); + m_logger.info("IPv6 not supported yet."); return; } if (ntohs(iph->tot_len) < 20) { - m_gtpu_log->warning("Invalid IP header length. IP length %d.\n", ntohs(iph->tot_len)); + m_logger.warning("Invalid IP header length. IP length %d.", ntohs(iph->tot_len)); return; } // Logging PDU info - m_gtpu_log->debug("SGi PDU -- IP version %d, Total length %d\n", iph->version, ntohs(iph->tot_len)); - m_gtpu_log->debug("SGi PDU -- IP src addr %s\n", srslte::gtpu_ntoa(iph->saddr).c_str()); - m_gtpu_log->debug("SGi PDU -- IP dst addr %s\n", srslte::gtpu_ntoa(iph->daddr).c_str()); + m_logger.debug("SGi PDU -- IP version %d, Total length %d", int(iph->version), ntohs(iph->tot_len)); + m_logger.debug("SGi PDU -- IP src addr %s", srslte::gtpu_ntoa(iph->saddr).c_str()); + m_logger.debug("SGi PDU -- IP dst addr %s", srslte::gtpu_ntoa(iph->daddr).c_str()); // Find user and control tunnel gtpu_fteid_it = m_ip_to_usr_teid.find(iph->daddr); @@ -227,16 +227,16 @@ void spgw::gtpu::handle_sgi_pdu(srslte::byte_buffer_t* msg) // Handle SGi packet if (usr_found == false && ctr_found == false) { - m_gtpu_log->debug("Packet for unknown UE.\n"); + m_logger.debug("Packet for unknown UE."); goto pkt_discard_out; } else if (usr_found == false && ctr_found == true) { - m_gtpu_log->debug("Packet for attached UE that is not ECM connected.\n"); - m_gtpu_log->debug("Triggering Donwlink Notification Requset.\n"); + m_logger.debug("Packet for attached UE that is not ECM connected."); + m_logger.debug("Triggering Donwlink Notification Requset."); m_gtpc->send_downlink_data_notification(spgw_teid); m_gtpc->queue_downlink_packet(spgw_teid, msg); return; } else if (usr_found == false && ctr_found == true) { - m_gtpu_log->error("User plane tunnel found without a control plane tunnel present.\n"); + m_logger.error("User plane tunnel found without a control plane tunnel present."); goto pkt_discard_out; } else { send_s1u_pdu(enb_fteid, msg); @@ -253,13 +253,13 @@ void spgw::gtpu::handle_s1u_pdu(srslte::byte_buffer_t* msg) srslte::gtpu_header_t header; srslte::gtpu_read_header(msg, &header, m_gtpu_log); - m_gtpu_log->debug("Received PDU from S1-U. Bytes=%d\n", msg->N_bytes); - m_gtpu_log->debug("TEID 0x%x. Bytes=%d\n", header.teid, msg->N_bytes); + m_logger.debug("Received PDU from S1-U. Bytes=%d", msg->N_bytes); + m_logger.debug("TEID 0x%x. Bytes=%d", header.teid, msg->N_bytes); int n = write(m_sgi, msg->msg, msg->N_bytes); if (n < 0) { - m_gtpu_log->error("Could not write to TUN interface.\n"); + m_logger.error("Could not write to TUN interface."); } else { - m_gtpu_log->debug("Forwarded packet to TUN interface. Bytes= %d/%d\n", n, msg->N_bytes); + m_logger.debug("Forwarded packet to TUN interface. Bytes= %d/%d", n, msg->N_bytes); } return; } @@ -279,26 +279,26 @@ void spgw::gtpu::send_s1u_pdu(srslte::gtp_fteid_t enb_fteid, srslte::byte_buffer header.length = msg->N_bytes; header.teid = enb_fteid.teid; - m_gtpu_log->debug("User plane tunnel found SGi PDU. Forwarding packet to S1-U.\n"); - m_gtpu_log->debug("eNB F-TEID -- eNB IP %s, eNB TEID 0x%x.\n", inet_ntoa(enb_addr.sin_addr), enb_fteid.teid); + m_logger.debug("User plane tunnel found SGi PDU. Forwarding packet to S1-U."); + m_logger.debug("eNB F-TEID -- eNB IP %s, eNB TEID 0x%x.", inet_ntoa(enb_addr.sin_addr), enb_fteid.teid); // Write header into packet int n; if (!srslte::gtpu_write_header(&header, msg, m_gtpu_log)) { - m_gtpu_log->error("Error writing GTP-U header on PDU\n"); + m_logger.error("Error writing GTP-U header on PDU"); goto out; } // Send packet to destination n = sendto(m_s1u, msg->msg, msg->N_bytes, 0, (struct sockaddr*)&enb_addr, sizeof(enb_addr)); if (n < 0) { - m_gtpu_log->error("Error sending packet to eNB\n"); + m_logger.error("Error sending packet to eNB"); } else if ((unsigned int)n != msg->N_bytes) { - m_gtpu_log->error("Mis-match between packet bytes and sent bytes: Sent: %d/%d\n", n, msg->N_bytes); + m_logger.error("Mis-match between packet bytes and sent bytes: Sent: %d/%d", n, msg->N_bytes); } out: - m_gtpu_log->debug("Deallocating packet after sending S1-U message\n"); + m_logger.debug("Deallocating packet after sending S1-U message"); m_pool->deallocate(msg); return; } @@ -306,7 +306,7 @@ out: void spgw::gtpu::send_all_queued_packets(srslte::gtp_fteid_t dw_user_fteid, std::queue& pkt_queue) { - m_gtpu_log->debug("Sending all queued packets\n"); + m_logger.debug("Sending all queued packets"); while (!pkt_queue.empty()) { srslte::byte_buffer_t* msg = pkt_queue.front(); send_s1u_pdu(dw_user_fteid, msg); @@ -320,11 +320,10 @@ void spgw::gtpu::send_all_queued_packets(srslte::gtp_fteid_t dw_ */ bool spgw::gtpu::modify_gtpu_tunnel(in_addr_t ue_ipv4, srslte::gtpc_f_teid_ie dw_user_fteid, uint32_t up_ctrl_teid) { - m_gtpu_log->info("Modifying GTP-U Tunnel.\n"); - m_gtpu_log->info("UE IP %s\n", srslte::gtpu_ntoa(ue_ipv4).c_str()); - m_gtpu_log->info( - "Downlink eNB addr %s, U-TEID 0x%x\n", srslte::gtpu_ntoa(dw_user_fteid.ipv4).c_str(), dw_user_fteid.teid); - m_gtpu_log->info("Uplink C-TEID: 0x%x\n", up_ctrl_teid); + m_logger.info("Modifying GTP-U Tunnel."); + m_logger.info("UE IP %s", srslte::gtpu_ntoa(ue_ipv4).c_str()); + m_logger.info("Downlink eNB addr %s, U-TEID 0x%x", srslte::gtpu_ntoa(dw_user_fteid.ipv4).c_str(), dw_user_fteid.teid); + m_logger.info("Uplink C-TEID: 0x%x", up_ctrl_teid); m_ip_to_usr_teid[ue_ipv4] = dw_user_fteid; m_ip_to_ctr_teid[ue_ipv4] = up_ctrl_teid; return true; @@ -336,7 +335,7 @@ bool spgw::gtpu::delete_gtpu_tunnel(in_addr_t ue_ipv4) if (m_ip_to_usr_teid.count(ue_ipv4)) { m_ip_to_usr_teid.erase(ue_ipv4); } else { - m_gtpu_log->error("Could not find GTP-U Tunnel to delete.\n"); + m_logger.error("Could not find GTP-U Tunnel to delete."); return false; } return true; @@ -348,7 +347,7 @@ bool spgw::gtpu::delete_gtpc_tunnel(in_addr_t ue_ipv4) if (m_ip_to_ctr_teid.count(ue_ipv4)) { m_ip_to_ctr_teid.erase(ue_ipv4); } else { - m_gtpu_log->error("Could not find GTP-C Tunnel info to delete.\n"); + m_logger.error("Could not find GTP-C Tunnel info to delete."); return false; } return true; diff --git a/srsepc/src/spgw/spgw.cc b/srsepc/src/spgw/spgw.cc index b698a1160..f000d5781 100644 --- a/srsepc/src/spgw/spgw.cc +++ b/srsepc/src/spgw/spgw.cc @@ -56,18 +56,11 @@ void spgw::cleanup() pthread_mutex_unlock(&spgw_instance_mutex); } -int spgw::init(spgw_args_t* args, - srslte::log_ref gtpu_log, - srslte::log_filter* gtpc_log, - srslte::log_filter* spgw_log, - const std::map& ip_to_imsi) +int spgw::init(spgw_args_t* args, srslte::log_ref gtpu_log, const std::map& ip_to_imsi) { int err; m_pool = srslte::byte_buffer_pool::get_instance(); - // Init log - m_spgw_log = spgw_log; - // Init GTP-U if (m_gtpu->init(args, this, m_gtpc, gtpu_log) != SRSLTE_SUCCESS) { srslte::console("Could not initialize the SPGW's GTP-U.\n"); @@ -75,12 +68,12 @@ int spgw::init(spgw_args_t* args, } // Init GTP-C - if (m_gtpc->init(args, this, m_gtpu, gtpc_log, ip_to_imsi) != SRSLTE_SUCCESS) { + if (m_gtpc->init(args, this, m_gtpu, ip_to_imsi) != SRSLTE_SUCCESS) { srslte::console("Could not initialize the S1-U interface.\n"); return SRSLTE_ERROR_CANT_START; } - m_spgw_log->info("SP-GW Initialized.\n"); + m_logger.info("SP-GW Initialized."); srslte::console("SP-GW Initialized.\n"); return SRSLTE_SUCCESS; } @@ -131,7 +124,7 @@ void spgw::run_thread() int n = select(max_fd + 1, &set, NULL, NULL, NULL); if (n == -1) { - m_spgw_log->error("Error from select\n"); + m_logger.error("Error from select"); } else if (n) { if (FD_ISSET(sgi, &set)) { /* @@ -142,25 +135,25 @@ void spgw::run_thread() * procedure fails (see handle_downlink_data_notification_acknowledgment and * handle_downlink_data_notification_failure) */ - m_spgw_log->debug("Message received at SPGW: SGi Message\n"); + m_logger.debug("Message received at SPGW: SGi Message"); sgi_msg = m_pool->allocate("spgw::run_thread::sgi_msg"); sgi_msg->N_bytes = read(sgi, sgi_msg->msg, buf_len); m_gtpu->handle_sgi_pdu(sgi_msg); } if (FD_ISSET(s1u, &set)) { - m_spgw_log->debug("Message received at SPGW: S1-U Message\n"); + m_logger.debug("Message received at SPGW: S1-U Message"); socklen_t addrlen = sizeof(src_addr_in); s1u_msg->N_bytes = recvfrom(s1u, s1u_msg->msg, buf_len, 0, (struct sockaddr*)&src_addr_in, &addrlen); m_gtpu->handle_s1u_pdu(s1u_msg); } if (FD_ISSET(s11, &set)) { - m_spgw_log->debug("Message received at SPGW: S11 Message\n"); + m_logger.debug("Message received at SPGW: S11 Message"); socklen_t addrlen = sizeof(src_addr_un); s11_msg->N_bytes = recvfrom(s11, s11_msg->msg, buf_len, 0, (struct sockaddr*)&src_addr_un, &addrlen); m_gtpc->handle_s11_pdu(s11_msg); } } else { - m_spgw_log->debug("No data from select.\n"); + m_logger.debug("No data from select."); } } m_pool->deallocate(s1u_msg);