Troubleshoot the DNS timeout Issues in MME

Introduction

This document describes the issues related to Domain Name System (DNS) timeout for the queries towards DNS in Mobile Management Entity (MME) for Serving GateWay (SGW) and Packet Data Network Gateway (PGW) selection.

Prerequisites

Requirements

 Cisco recommends that you have knowledge of these topics:

• StarOS
• MME functionality related to DNS

Components used

The information in this document is based on these software and hardware versions:

• DNS
• MME

The information in this document was created from the devices in a specific lab environment. All of the devices used in this document started with a cleared (default) configuration. If your network is live, ensure that you understand the potential impact of any command.

Background Information

DNS

The DNS turns domain names into IP addresses, which browsers use to load ABCD pages. Every device connected to the networks has its own IP address, which is used by other devices to locate the device.

From a mobility perspective, DNS is the external server that is used for Access Point Name (APN) and URL resolution based on its connectivity with the nodes in the network.

1. MME to DNS connectivity: Used for APN resolution for SPGW selection

2. SPGW to DNS connectivity: Used for URL resolution to reach Internet Service Provider (ISP)

Types of Records used in DNS.

1. A/AAA record: Used to define IPv4 and IPv6 host address mapped to the fully qualified name of the host where A record used for IPv4 and Authentication, Authorization and Accounting (AAA) used for IPv6.

2. NAPTR record: Used as a lookup service that points towards a Service record (SRV) and A/AAA records for the SPGW selection process for the 4G APN and TAC resolution.

3. SRV record: Used as a lookup to map between a Name Authority Pointer (NAPTR) and A/AAA record.

Example: Observe how the A/SRV/NAPTR is mapped.

MME Functionality Related to DNS

• The basic function of MME related to DNS is for the purpose of SGW and PGW selection based on DNS queries.
• Cisco MME has its own DNS cache which helps to avoid frequent queries to external servers and stores every query performed in the MME DNS cache to reduce the need to send the query to an external DNS server.
• When the UE registers to an Evolved Packet System (EPS) network, it must be assigned the appropriate SGWs and PGWs. The MME makes the GW selection based on DNS.
• NAPTR query is used to make GW address resolution.
• Based on the DNS query, MME determines the interface between S-GW and P-GW.

The Procedure of SPGW Selection 

• MME performs an initial DNS query to obtain a list of GW identities and priorities
• S-GW selection done based on Tracking Area Identifier(TAI)
• P-GW selection done based on APN
• MME selects the GW based on priority information or MME configuration
• Then a second DNS query is made to get the IP addresses of the desired GW.

So as per the procedure, MME always makes 2 DNS queries to get GW IP addressed which is explained.

Query 1: For the first query done via APN or TAI, you get an SRV profile mapped with it or directly A record output mapped in response.

Query 2: Further it makes a query to the SRV profile and sends it as a replacement string to get the GW IP.

For example:

Query Name: abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org
Query Type: NAPTR      TTL: 515 seconds
Answer:
Order: 100            Preference: 50000
Flags: a             Service: x-3gpp-pgw:x-s5-gtp:x-s8-gtp:x-gn:x-gp
Regular Expression:
Replacement: _nodes._pgw.epc.mncXXX.mccYYY.3gppnetwork.org

Query Name: _nodes._pgw.epc.mncXXX.mccYYY.3gppnetwork.org
Query Type: NAPTR      TTL: 515 seconds
Answer:
Order: 100            Preference: 50000
Flags: a            Service: x-3gpp-pgw:x-s5-gtp:x-s8-gtp:x-gn:x-gp

Regular Expression: topoff.pgw- s5s8.node.epc.mncXXX.mccYYY.3gppnetwork.org

Query Name: topoff.pgw- s5s8.node.epc.mncXXX.mccYYY.3gppnetwork.org
Query Type: A      TTL: 646 seconds
Answer:
IP Address: X.X.X.X

Problem

1. When you do NAPTR query from MME for APN abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org and get a DNS timeout at MME.

Note: String +nc-nr is the new string added to the 5G service and added against each NAPTR Resource Record (RR) to identify the service interface.

"x-3gpp-pgw:x-s5-gtp+nc-nr:x-s8-gtp:x-gn:x-gp"

Note: +nc-nr is the new string based on the 5G service so MME needs to support this service to work because when MME makes a DNS query and get a response to check that particular service is enabled or not in MME.

[gn]SGSN-MME# dns-client query client-name dnsclient query-type NAPTR query-name abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org
Wednesday October 27 17:06:20 ICT 2021
Query Name: abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org
Query Type: NAPTR      TTL: 0 seconds
Answer: -Negative Reply-
Failure Reason: DNS query timed out

2. In PCAP traces, it was found that the DNS server receives the query and in response sends 30 to 35 replacements against each APN due to which packet size becomes 4186 bytes and MME initiates TCP connection.

3. You can see that DNS received query request and send the response but without any content with just one flag as "Message is truncated". This is observed only for the case where the response message is truncated and the rest of the 4G responses works fine when the message is not truncated.

The reason for the truncated message is when a number of replacements mapped against the APN are more than 30 and it increases the size of the message and sends the message flag truncated in response. The total size for the response message is 4181 bytes as a TCP payload (refer to the image).

Once receive this response at the MME, MME initiates the TCP connection with DNS.

 From MME to DNS

• Frame 31 – MME sends a query to DNS
• Frame 32 – DNS sends a response with the flag set as “Message is truncated”
• Frame 33/34/35 – TCP connection established between MME and DNS and exchange their own capabilities

In the given snapshot, you can see Maximum Segment Size (MSS) send from MME is 9060.

When MME makes a query for which DNS send a response with "Message is truncated" and it has no other information after which based on DNS response MME initiates TCP connection.

From DNS to MME

• MME sends a query after TCP connection
•  DNS acknowledges it.
•  DNS sends a response with the flag set as “Message is not truncated” because MSS shared with DNS is set to 9060 bytes and it sends the entire response in one go.
•  MME responds with an ACK with no content
•  DNS  sends the ACK to the content in Message 38 where the payload is 4181 bytes
• MME sends TCP to reset and close the connections as soon as it receives the last fragment.

When MME receives the whole payload in 2 to 3 segments or in one attempt from DNS, MME sends a TCP reset message.

DNS commands to troubleshoot

show dns-client statistics
show dns-client statistics client <DNS Client Name>
show dns-client cache client <client name> [query-name <query-name>[query-type <NAPTR | AAAA | A>] | [query-type <NAPTR | AAAA | A>]]
dns-client query client-name <client name> query-type <NAPTR | AAAA> [query-name <query name>].show port datalink counters

Commands to check if there were any problem internal to the starOS system where request is not able to reach from demux vpnmgr to DNS app in sessmgrs

show port npu counters
show cloud configuration
show iftask stats summary
show npu utilization table
show iftask port-stats card <card>   ---- for all active SF cards
show iftask iomux-stats card <card>  ---- for all active SF cards

MON SUB to be captured with options enabled (verbosity 5,Y,S,34,35,19,A,26)

PCAP traces to be captured

DNS cache flush commands

clear dns-client <client-name> cache

Test Scenario

1. Capture all required debug logs/traces with dedicated test and enable the logs at the same time when  subscriber browses with problematic APN 

2. Ensure every time a test scenario is performed, the subscriber needs to do a fresh attach to flush the subscriber.

3. For test purposes, assign one tester and that tester need to do a dedicated test with its IMSI and need to access that problematic APN: abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org.

  logging filter active facility vpn level debug         ------ debug level logs
  logging filter active facility tcpdemux level debug    ------ debug level logs
  logging monitor msid <MSID number>                     ------ (these logging command to be executed in config mode)

Troubleshoot

1. Check the outputs of all commands mentioned to confirm if there is any packet drop internal to the system.

2. Check the statistics to confirm the frequency of DNS timeouts increase in the node.

[gn]SGSN-MME# show dns-client statistics client dnsclient
Friday August 20 13:31:48 ICT 2021
DNS Usage Statistics:
---------------------
Query Type             Attempts       Successes        Failures
A                    2430996860      2410410937        20546467
SRV                  1325520986      1325516557            4429
AAAA                 3939810089               0      3939810089
NAPTR                 480586697       432853033        47732791
PTR                           0               0               0
Total                3881947336      4168780527      4008093776

…
Total Resolver Queries: 4480708
Successful Queries:     670040
Query Timeouts:         409717  
Domain Not Found:       2455918
Connection Refused:     0
Other Failures:         580612

After you run these commands to capture the statistics for multiple iterations and observe that query timeouts are increased gradually but there were no packet drops between Demux and sessmgrs so which concludes no problem with the internal system

Further to check any issues with external connectivity or configuration issue in DNS, you directly perform the query for the replacements values manually from MME instead of APN as shown in the image, where it gets resolved properly without any delay and concludes there is no problem with external connectivity and configuration as well.

[gn]SGSN-MME# dns-client query client-name dnsclient query-name TOPON.test.NODE.EPC.MNCXXX.MCCYYY.3GPPNETWORK.ORG
Monday August 02 18:51:29 ICT 2021
Query Name: TOPON.test.NODE.EPC.MNCXXX.MCCYYY.3GPPNETWORK.ORG
Query Type: A          TTL: 1038 seconds
Answer:
IP Address: X.X.X.X ------ resolve properly and gave IP

The problem is between DNS and SGSN-MME where you can see DNS send responses with replacement values as topon and MME must query again for the topon entries but which did not happen otherwise if we manually do the query resolution is successful

As per the command outputs and traces, it was clear that when you query APN,  you get responses with 30 replacements via TCP connection in fragments and while MME acknowledges these fragments it sends reset to DNS.

Since MME sends TCP to reset we can see in MME where DNS query shows error as query timeout and till this point of time we don’t see those 30 replacements values in MME command outputs since fragments were not acknowledged completely and before completion of this process, MME sends TCP to reset.

Debug logs analysis

For abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org

2021-Oct-27+17:06:20.910 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:14585, UDP, Sent time 1635329180, Timeout set 1635329183  ---- timer is set here
2021-Oct-27+17:06:20.910 [vpn 5919 info] [9/0/11730 <vpnmgr:6> dns_resolver.c:323] [software internal system syslog] Sent out a DNS Query abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org to DNS Server   --------- DNS query is send for the first time
2021-Oct-27+17:06:20.911 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Init, While Sending Query
2021-Oct-27+17:06:20.911 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Open with DHost
2021-Oct-27+17:06:20.911 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:14585, TCP, Sent time 1635329180, Timeout set 1635329183 ------------ DNS query is send for the second time
2021-Oct-27+17:06:20.911 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Successful - DHost-Id = 6766924, Sock_fd = 21
2021-Oct-27+17:06:21.008 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP READ, Kernel Closed, EOF - DHost-Id = 6766924, Sock_fd = 21, errno = 115, req_read_len = 0
2021-Oct-27+17:06:21.008 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection close - DHost-Id = 6766924, Sock_fd = 21
2021-Oct-27+17:06:23.019 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:14585, TCP, Timeout detected: 1635329183 ---------------- Timeout detected here
2021-Oct-27+17:06:23.019 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Init, While Sending Query --------------------- Query is send again
2021-Oct-27+17:06:23.019 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Open with DHost
2021-Oct-27+17:06:23.019 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:14585, TCP, Sent time 1635329183, Timeout set 1635329186 ------- Again send the query with new timer value set
2021-Oct-27+17:06:23.019 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Successful - DHost-Id = 6504921, Sock_fd = 23
2021-Oct-27+17:06:26.036 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:14585, TCP, Timeout detected: 1635329186 ---------------- Timeout detected here
2021-Oct-27+17:06:26.036 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:35196, UDP, Timeout detected: 1635329186 ---------------- Timeout detected here

 Another example abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org

2021-Oct-27+17:06:27.257 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:19140, UDP, Sent time 1635329187, Timeout set 1635329190 ---- timer is set here
2021-Oct-27+17:06:27.257 [vpn 5919 info] [9/0/11730 <vpnmgr:6> dns_resolver.c:323] [software internal system syslog] Sent out a DNS Query abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.org to DNS Server --------- Query send for the first time
2021-Oct-27+17:06:27.258 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Init, While Sending Query
2021-Oct-27+17:06:27.258 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Open with DHost
2021-Oct-27+17:06:27.258 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:19140, TCP, Sent time 1635329187, Timeout set 1635329190  -------- Same Query send for the second time
2021-Oct-27+17:06:27.258 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Successful - DHost-Id = 7201531, Sock_fd = 22
2021-Oct-27+17:06:27.309 [vpn 5921 debug] [7/0/12843 <sessmgr:79> dns_snaptr.c:1466] [software internal system syslog] VPN DEBUG : snaptr_match_valid_entries Initial ue_usage_type:0 nc_nr:0   ----- snaptr match starts
2021-Oct-27+17:06:27.309 [vpn 5921 debug] [7/0/12843 <sessmgr:79> dns_snaptr.c:237] [software internal system syslog] VPN DEBUG : snaptr_compare_service_protocol_set rr_service_parameter x-3gpp-mme:x-gn, inp_svc_param x-3gpp-sgw:x-s5-gtp ue_usage_type_enabled:0 nc_nr_enabled:0   ------- nc_nr enabled which I mentioned earlier
2021-Oct-27+17:06:27.309 [vpn 5921 debug] [7/0/12843 <sessmgr:79> dns_snaptr.c:237] [software internal system syslog] VPN DEBUG : snaptr_compare_service_protocol_set rr_service_parameter x-3gpp-sgw:x-s5-gtp:x-s8-gtp, inp_svc_param x-3gpp-sgw:x-s5-gtp ue_usage_type_enabled:0 nc_nr_e:nabled0
2021-Oct-27+17:06:27.309 [vpn 5921 debug] [7/0/12843 <sessmgr:79> dns_snaptr.c:279] [software internal system syslog] VPN DEBUG : 0.rr_prot_token x-s5-gtp, input token x-s5-gtp
2021-Oct-27+17:06:27.309 [vpn 5921 debug] [7/0/12843 <sessmgr:79> dns_snaptr.c:323] [software internal system syslog] VPN DEBUG : 4.Success Selected Protocol(Normal):x-s5-gtp  ----------- snaptr protocol matched
2021-Oct-27+17:06:30.057 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:19140, TCP, Timeout detected: 1635329190 -------- TCP timeout happens
2021-Oct-27+17:06:30.057 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Init, While Sending Query ----- Again TCP connection initiated
2021-Oct-27+17:06:30.057 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Open with DHost
2021-Oct-27+17:06:30.057 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:19140, TCP, Sent time 1635329190, Timeout set 1635329193 ------ New timer value set with send query
2021-Oct-27+17:06:30.057 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection Successful - DHost-Id = 7136007, Sock_fd = 21
2021-Oct-27+17:06:30.158 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP READ, Kernel Closed, EOF - DHost-Id = 7136007, Sock_fd = 21, errno = 115, req_read_len = 0 – Error because TCP connection is busy because previous connection is not closed
2021-Oct-27+17:06:30.158 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] TCP Connection close - DHost-Id = 7136007, Sock_fd = 21 -------- Connection closed
2021-Oct-27+17:06:30.171 [vpn 5921 debug] [14/0/12709 <sessmgr:15> dns_snaptr.c:1466] [software internal system syslog] VPN DEBUG : snaptr_match_valid_entries Initial ue_usage_type:0 nc_nr:0 --- again snaptr match takes place
2021-Oct-27+17:06:30.171 [vpn 5921 debug] [14/0/12709 <sessmgr:15> dns_snaptr.c:237] [software internal system syslog] VPN DEBUG : snaptr_compare_service_protocol_set rr_service_parameter x-3gpp-mme:x-gn, inp_svc_param x-3gpp-sgw:x-s5-gtp ue_usage_type_enabled:0 nc_nr_enabled:0
2021-Oct-27+17:06:30.171 [vpn 5921 debug] [14/0/12709 <sessmgr:15> dns_snaptr.c:237] [software internal system syslog] VPN DEBUG : snaptr_compare_service_protocol_set rr_service_parameter x-3gpp-sgw:x-s5-gtp:x-s8-gtp, inp_svc_param x-3gpp-sgw:x-s5-gtp ue_usage_type_enabled:0 nc_nr_enabled:0
2021-Oct-27+17:06:30.171 [vpn 5921 debug] [14/0/12709 <sessmgr:15> dns_snaptr.c:279] [software internal system syslog] VPN DEBUG : 0.rr_prot_token x-s5-gtp, input token x-s5-gtp
2021-Oct-27+17:06:33.073 [vpn 5456 info] [9/0/11730 <vpnmgr:6> vpnmgr_func.c:8011] [software internal system syslog] query:19140, TCP, Timeout detected: 1635329193 -----TCP timeout detected

From logs, it indicates that after the first timeout MME sends error 115 for the next retries because the first TCP connection is still not closed at the socket.  Timeout for the first TCP connection has happened and the previous connection was not closed.

A new connection is initiated which is on the same socket where the previous connection was established and not cleared. You see the error 115 (operations in progress) even though the new connection was formed but somehow the socket did not close the previous connection after the first timeout.

Solution

Restart the vpnmgr of the DNS context. A software fix is yet to be provided.