From 411946c752048514b64001744ff72f164dcfc622 Mon Sep 17 00:00:00 2001 From: Francisco Date: Tue, 2 Feb 2021 15:13:29 +0000 Subject: [PATCH] Improvements on GTPU message logging - Avoid multiple lines per each SDU Rx or Tx - log info relative to source and destination of each SDU - log info relative to whether the Rx SDU has been forwarded into a tunnel - log info relative to whether the Rx SDUs are being buffered. --- srsenb/hdr/stack/upper/gtpu.h | 10 ++- srsenb/src/stack/upper/gtpu.cc | 116 +++++++++++++++++++-------------- srsenb/test/upper/gtpu_test.cc | 12 +++- 3 files changed, 79 insertions(+), 59 deletions(-) diff --git a/srsenb/hdr/stack/upper/gtpu.h b/srsenb/hdr/stack/upper/gtpu.h index 27dd39ded..5e9c91218 100644 --- a/srsenb/hdr/stack/upper/gtpu.h +++ b/srsenb/hdr/stack/upper/gtpu.h @@ -61,12 +61,6 @@ private: static const int GTPU_PORT = 2152; void rem_tunnel(uint32_t teidin); - void send_pdu_to_tunnel(uint16_t rnti, - uint32_t lcid, - srslte::unique_byte_buffer_t pdu, - uint32_t teidout, - uint32_t spgw_addr, - int pdcp_sn = -1); srslte::byte_buffer_pool* pool = nullptr; stack_interface_gtpu_lte* stack = nullptr; @@ -126,6 +120,8 @@ private: // Socket file descriptor int fd = -1; + void send_pdu_to_tunnel(tunnel& tx_tun, srslte::unique_byte_buffer_t pdu, int pdcp_sn = -1); + void echo_response(in_addr_t addr, in_port_t port, uint16_t seq); void error_indication(in_addr_t addr, in_port_t port, uint32_t err_teid); void end_marker(uint32_t teidin); @@ -138,6 +134,8 @@ private: uint32_t next_teid_in = 0; tunnel* get_tunnel(uint32_t teidin); + + void log_message(tunnel& tun, bool is_rx, srslte::span pdu, int pdcp_sn = -1); }; } // namespace srsenb diff --git a/srsenb/src/stack/upper/gtpu.cc b/srsenb/src/stack/upper/gtpu.cc index d493c137e..775b8b36d 100644 --- a/srsenb/src/stack/upper/gtpu.cc +++ b/srsenb/src/stack/upper/gtpu.cc @@ -90,41 +90,25 @@ void gtpu::stop() // gtpu_interface_pdcp void gtpu::write_pdu(uint16_t rnti, uint32_t lcid, srslte::unique_byte_buffer_t pdu) { - send_pdu_to_tunnel(rnti, - lcid, - std::move(pdu), - tunnels[ue_teidin_db[rnti][lcid][0]].teid_out, - tunnels[ue_teidin_db[rnti][lcid][0]].spgw_addr); + tunnel& tx_tun = tunnels[ue_teidin_db.at(rnti)[lcid][0]]; + log_message(tx_tun, false, srslte::make_span(pdu)); + send_pdu_to_tunnel(tx_tun, std::move(pdu)); } -void gtpu::send_pdu_to_tunnel(uint16_t rnti, - uint32_t lcid, - srslte::unique_byte_buffer_t pdu, - uint32_t teidout, - uint32_t spgw_addr, - int pdcp_sn) -{ - logger.info(pdu->msg, pdu->N_bytes, "TX PDU, RNTI: 0x%x, LCID: %d, n_bytes=%d", rnti, lcid, pdu->N_bytes); +void gtpu::send_pdu_to_tunnel(tunnel& tx_tun, srslte::unique_byte_buffer_t pdu, int pdcp_sn) +{ // Check valid IP version struct iphdr* ip_pkt = (struct iphdr*)pdu->msg; if (ip_pkt->version != 4 && ip_pkt->version != 6) { logger.error("Invalid IP version to SPGW"); return; } - if (ip_pkt->version == 4) { - if (ntohs(ip_pkt->tot_len) != pdu->N_bytes) { - logger.error("IP Len and PDU N_bytes mismatch"); - } - logger.debug("Tx S1-U PDU -- IP version %d, Total length %d", int(ip_pkt->version), ntohs(ip_pkt->tot_len)); - logger.debug("Tx S1-U PDU -- IP src addr %s", srslte::gtpu_ntoa(ip_pkt->saddr).c_str()); - logger.debug("Tx S1-U PDU -- IP dst addr %s", srslte::gtpu_ntoa(ip_pkt->daddr).c_str()); - } gtpu_header_t header; header.flags = GTPU_FLAGS_VERSION_V1 | GTPU_FLAGS_GTP_PROTOCOL; header.message_type = GTPU_MSG_DATA_PDU; header.length = pdu->N_bytes; - header.teid = teidout; + header.teid = tx_tun.teid_out; if (pdcp_sn >= 0) { header.flags |= GTPU_FLAGS_EXTENDED_HDR; @@ -138,7 +122,7 @@ void gtpu::send_pdu_to_tunnel(uint16_t rnti, struct sockaddr_in servaddr; servaddr.sin_family = AF_INET; - servaddr.sin_addr.s_addr = htonl(spgw_addr); + servaddr.sin_addr.s_addr = htonl(tx_tun.spgw_addr); servaddr.sin_port = htons(GTPU_PORT); if (!gtpu_write_header(&header, pdu.get(), gtpu_log)) { @@ -163,6 +147,13 @@ uint32_t gtpu::add_bearer(uint16_t rnti, uint32_t lcid, uint32_t addr, uint32_t ue_teidin_db[rnti][lcid].push_back(teid_in); + logger.info("Adding bearer for rnti: 0x%x, lcid: %d, addr: 0x%x, teid_out: 0x%x, teid_in: 0x%x", + rnti, + lcid, + addr, + teid_out, + teid_in); + if (props != nullptr) { if (props->flush_before_teidin_present) { tunnel& after_tun = tunnels.at(props->flush_before_teidin); @@ -179,13 +170,6 @@ uint32_t gtpu::add_bearer(uint16_t rnti, uint32_t lcid, uint32_t addr, uint32_t } } - logger.info("Adding bearer for rnti: 0x%x, lcid: %d, addr: 0x%x, teid_out: 0x%x, teid_in: 0x%x", - rnti, - lcid, - addr, - teid_out, - teid_in); - return teid_in; } @@ -296,38 +280,23 @@ void gtpu::handle_gtpu_s1u_rx_packet(srslte::unique_byte_buffer_t pdu, const soc uint16_t rnti = rx_tun.rnti; uint16_t lcid = rx_tun.lcid; + log_message(rx_tun, true, srslte::make_span(pdu)); + if (lcid < SRSENB_N_SRB || lcid >= SRSENB_N_RADIO_BEARERS) { logger.error("Invalid LCID for DL PDU: %d - dropping packet", lcid); return; } - struct iphdr* ip_pkt = (struct iphdr*)pdu->msg; if (ip_pkt->version != 4 && ip_pkt->version != 6) { - logger.error("Invalid IP version to SPGW"); return; } - if (ip_pkt->version == 4) { - if (ntohs(ip_pkt->tot_len) != pdu->N_bytes) { - logger.error("IP Len and PDU N_bytes mismatch"); - } - logger.debug("Rx S1-U PDU -- IPv%d, src=%s, dst=%s, length=%d", - int(ip_pkt->version), - srslte::gtpu_ntoa(ip_pkt->saddr).c_str(), - srslte::gtpu_ntoa(ip_pkt->daddr).c_str(), - ntohs(ip_pkt->tot_len)); - } - if (rx_tun.fwd_teid_in_present) { tunnel& tx_tun = tunnels.at(rx_tun.fwd_teid_in); - logger.info("Forwarding GTPU PDU rnti=0x%x, lcid=%d, n_bytes=%d", rnti, lcid, pdu->N_bytes); - send_pdu_to_tunnel(rnti, lcid, std::move(pdu), tx_tun.teid_out, tx_tun.spgw_addr); + send_pdu_to_tunnel(tx_tun, std::move(pdu)); } else if (rx_tun.prior_teid_in_present) { - logger.info( - pdu->msg, pdu->N_bytes, "Buffering RX GTPU PDU rnti=0x%x, lcid=%d, n_bytes=%d", rnti, lcid, pdu->N_bytes); rx_tun.buffer.push_back(std::move(pdu)); } else { - logger.info(pdu->msg, pdu->N_bytes, "RX GTPU PDU rnti=0x%x, lcid=%d, n_bytes=%d", rnti, lcid, pdu->N_bytes); uint32_t pdcp_sn = -1; if (header.flags & GTPU_FLAGS_EXTENDED_HDR and header.next_ext_hdr_type == GTPU_EXT_HEADER_PDCP_PDU_NUMBER) { pdcp_sn = (header.ext_buffer[1] << 8u) + header.ext_buffer[2]; @@ -396,8 +365,8 @@ int gtpu::create_dl_fwd_tunnel(uint32_t rx_teid_in, uint32_t tx_teid_in) // Get all buffered PDCP PDUs, and forward them through tx tunnel std::map pdus = pdcp->get_buffered_pdus(rx_tun.rnti, rx_tun.lcid); for (auto& pdu_pair : pdus) { - send_pdu_to_tunnel( - rx_tun.rnti, rx_tun.lcid, std::move(pdu_pair.second), tx_tun.teid_out, tx_tun.spgw_addr, pdu_pair.first); + log_message(tx_tun, false, srslte::make_span(pdu_pair.second), pdu_pair.first); + send_pdu_to_tunnel(tx_tun, std::move(pdu_pair.second), pdu_pair.first); } return SRSLTE_SUCCESS; @@ -503,6 +472,53 @@ gtpu::tunnel* gtpu::get_tunnel(uint32_t teidin) return &it->second; } +void gtpu::log_message(tunnel& tun, bool is_rx, srslte::span pdu, int pdcp_sn) +{ + fmt::basic_memory_buffer strbuf; + struct iphdr* ip_pkt = (struct iphdr*)pdu.data(); + if (ip_pkt->version != 4 && ip_pkt->version != 6) { + logger.error("%s SDU with invalid IP version %s SPGW", is_rx ? "Received" : "Sending", is_rx ? "from" : "to"); + return; + } + + const char* dir = "Tx"; + fmt::memory_buffer strbuf2; + if (is_rx) { + dir = "Rx"; + fmt::format_to(strbuf2, "{}:0x{:0x} > ", srslte::gtpu_ntoa(htonl(tun.spgw_addr)), tun.teid_in); + if (tun.prior_teid_in_present) { + fmt::format_to(strbuf2, "DL (buffered), "); + } else if (tun.fwd_teid_in_present) { + tunnel& tx_tun = tunnels.at(tun.fwd_teid_in); + fmt::format_to(strbuf2, "{}:0x{:0x} (forwarded), ", srslte::gtpu_ntoa(htonl(tx_tun.spgw_addr)), tx_tun.teid_in); + } else { + fmt::format_to(strbuf2, "DL, "); + } + } else { + if (pdcp_sn >= 0) { + fmt::format_to(strbuf2, "DL PDCP SDU SN={} ", pdcp_sn); + } else { + fmt::format_to(strbuf2, "UL "); + } + fmt::format_to(strbuf2, "> {}:0x{:0x}, ", srslte::gtpu_ntoa(htonl(tun.spgw_addr)), tun.teid_in); + } + fmt::format_to(strbuf, + "{} S1-U SDU, {}rnti=0x{:0x}, lcid={}, n_bytes={}, IPv{}", + dir, + fmt::to_string(strbuf2), + tun.rnti, + tun.lcid, + pdu.size(), + (int)ip_pkt->version); + if (ip_pkt->version == 4) { + fmt::format_to(strbuf, " {} > {}", srslte::gtpu_ntoa(ip_pkt->saddr), srslte::gtpu_ntoa(ip_pkt->daddr)); + if (ntohs(ip_pkt->tot_len) != pdu.size()) { + logger.error("IP Len and PDU N_bytes mismatch"); + } + } + logger.info(pdu.data(), pdu.size(), fmt::to_string(strbuf)); +} + /**************************************************************************** * Class to handle MCH packet handling ***************************************************************************/ diff --git a/srsenb/test/upper/gtpu_test.cc b/srsenb/test/upper/gtpu_test.cc index 4827c9415..08672be89 100644 --- a/srsenb/test/upper/gtpu_test.cc +++ b/srsenb/test/upper/gtpu_test.cc @@ -136,12 +136,18 @@ int test_gtpu_direct_tunneling() srslte::net_utils::set_sockaddr(&senb_sockaddr, senb_addr_str, GTPU_PORT); srslte::net_utils::set_sockaddr(&sgw_sockaddr, sgw_addr_str, GTPU_PORT); srslte::net_utils::set_sockaddr(&tenb_sockaddr, tenb_addr_str, GTPU_PORT); - uint32_t tenb_addr = ntohl(tenb_sockaddr.sin_addr.s_addr), sgw_addr = ntohl(sgw_sockaddr.sin_addr.s_addr); + uint32_t tenb_addr = ntohl(tenb_sockaddr.sin_addr.s_addr); + uint32_t senb_addr = ntohl(senb_sockaddr.sin_addr.s_addr); + uint32_t sgw_addr = ntohl(sgw_sockaddr.sin_addr.s_addr); srslte::unique_byte_buffer_t pdu; // Initiate layers - srsenb::gtpu senb_gtpu(srslog::fetch_basic_logger("GTPU1")), tenb_gtpu(srslog::fetch_basic_logger("GTPU2")); + srslog::basic_logger& logger1 = srslog::fetch_basic_logger("GTPU1"); + logger1.set_hex_dump_max_size(2048); + srslog::basic_logger& logger2 = srslog::fetch_basic_logger("GTPU2"); + logger2.set_hex_dump_max_size(2048); + srsenb::gtpu senb_gtpu(logger1), tenb_gtpu(logger2); stack_tester senb_stack, tenb_stack; pdcp_tester senb_pdcp, tenb_pdcp; senb_gtpu.init(senb_addr_str, sgw_addr_str, "", "", &senb_pdcp, &senb_stack, false); @@ -164,7 +170,7 @@ int test_gtpu_direct_tunneling() gtpu::bearer_props props; props.flush_before_teidin_present = true; props.flush_before_teidin = tenb_teid_in; - uint32_t dl_tenb_teid_in = tenb_gtpu.add_bearer(rnti2, drb1, 0, 0, &props); + uint32_t dl_tenb_teid_in = tenb_gtpu.add_bearer(rnti2, drb1, senb_addr, 0, &props); props = {}; props.forward_from_teidin_present = true; props.forward_from_teidin = senb_teid_in;