MMEでのDNSタイムアウトの問題のトラブルシューティング

概要

このドキュメントでは、Serving GateWay(SGW)およびPacket Data Network Gateway(PGW)の選択のためのMobile Management Entity(MME)のDNSに対するクエリのドメインネームシステム(DNS)タイムアウトに関する問題について説明します。

前提条件

要件

 次の項目に関する知識があることが推奨されます。

• StarOS
• DNSに関連するMME機能

使用するコンポーネント

このドキュメントの情報は、次のソフトウェアとハードウェアのバージョンに基づいています。

• DNS
• MME

このドキュメントの情報は、特定のラボ環境にあるデバイスに基づいて作成されました。このドキュメントで使用するすべてのデバイスは、初期（デフォルト）設定の状態から起動しています。本稼働中のネットワークでは、各コマンドによって起こる可能性がある影響を十分確認してください。

背景説明

DNS

DNSは、ドメイン名をIPアドレスに変換します。このアドレスは、ブラウザがABCDページのロードに使用します。ネットワークに接続された各デバイスには独自のIPアドレスがあり、これは他のデバイスがデバイスを特定するために使用します。

モビリティの観点から見ると、DNSは、ネットワーク内のノードとの接続に基づいて、アクセスポイント名(APN)およびURL解決に使用される外部サーバです。

1. MMEからDNSへの接続：SPGW選択のAPN解決に使用

2. SPGWからDNSへの接続：インターネットサービスプロバイダー(ISP)に到達するためのURL解決に使用

DNSで使用されるレコードの種類。

1. A/AAAレコード：IPv4に使用されるAレコードと、IPv6に使用される認証、許可、アカウンティング(AAA)が使用されるホストの完全修飾名にマッピングされるIPv4およびIPv6ホストアドレスを定義するために使用されます。

2. NAPTRレコード：4G APNおよびTACの解決のためのSPGW選択プロセスのサービスレコード(SRV)およびA/AAAレコードを指すルックアップサービスとして使用されます。

3. SRVレコード：名前権限ポインタ(NAPTR)とA/AAAレコードの間のマッピングのためのルックアップとして使用されます。

例：A/SRV/NAPTRがどのようにマッピングされているかを確認します。

DNSに関連するMME機能

• DNSに関連するMMEの基本機能は、DNSクエリに基づくSGWとPGWの選択です。
• Cisco MMEには独自のDNSキャッシュがあり、外部サーバへの頻繁なクエリを回避し、MME DNSキャッシュで実行されたすべてのクエリを保存することで、クエリを外部DNSサーバに送信する必要性を減らします。
• UEがEvolved Packet System(EPS)ネットワークに登録する場合、適切なSGWとPGWを割り当てる必要があります。MMEは、DNSに基づいてゲートウェイを選択する。
• NAPTRクエリは、GWアドレス解決に使用されます。
• MMEは、DNSクエリに基づいて、S-GWとP-GW間のインターフェイスを決定します。

SPGW選択手順 

• MMEは初期DNSクエリを実行して、ゲートウェイのIDと優先順位のリストを取得します
• トラッキングエリア識別子(TAI)に基づいてS-GWの選択を行う
• P-GWの選択はAPNに基づいて行われる
• MMEは、優先度情報またはMME設定に基づいてGWを選択する
• 次に、目的のゲートウェイのIPアドレスを取得するための第2のDNSクエリが行われます。

そのため、手順に従って、MMEは常に2つのDNSクエリを実行して、説明されているGW IPアドレスを取得します。

クエリ1:APNまたはTAIを介して行われた最初のクエリでは、SRVプロファイルがマッピングされているか、または応答でマッピングされた直接Aレコード出力を取得します。

クエリ2:さらに、SRVプロファイルにクエリーを作成し、GW IPを取得するための置換文字列として送信します。

以下に、いくつかの例を示します。

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

問題

1. APN abcd.apn.epc.mncXXX.mccYYY.3gppnetwork.orgのMMEからNAPTRクエリを実行し、MMEでDNSタイムアウトを取得する場合。

注：String +nc-nrは、5Gサービスに追加され、サービスインターフェイスを識別するために各NAPTRリソースレコード(RR)に対して追加された新しい文字列です。

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

注：+nc-nrは5Gサービスに基づく新しい文字列です。MMEがDNSクエリを実行し、特定のサービスがMMEで有効か無効かを確認するための応答を取得する場合、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. PCAPトレースでは、DNSサーバがクエリを受信し、応答で各APNに対して30 ～ 35個の置換を送信していることが判明しました。パケットサイズが4186バイトになり、MMEがTCP接続を開始します。

3. DNSがクエリ要求を受信し、応答を送信したが、「メッセージが切り捨てられました」というフラグが1つだけのコンテンツがないことがわかります。 これは、応答メッセージが切り捨てられ、残りの4G応答がメッセージが切り捨てられていない場合にのみ問題なく動作する場合にのみ発生します。

切り捨てられたメッセージの理由は、APNに対してマッピングされた多数の置換が30を超え、メッセージのサイズが増加し、応答として切り捨てられたメッセージフラグを送信する場合です。応答メッセージの合計サイズは、TCPペイロードとして4181バイトです（図を参照）。

MMEでこの応答を受信すると、MMEはDNSとのTCP接続を開始します。

 MMEからDNSへ

• フレーム31:MMEがDNSにクエリを送信します
• フレーム32:DNSは、「メッセージが切り捨てられた」フラグを設定した応答を送信します
• フレーム33/34/35:MMEとDNSの間で確立され、独自の機能を交換するTCP接続

指定されたスナップショットでは、MMEから送信される最大セグメントサイズ(MSS)が9060であることがわかります。

MMEが「Message is truncated」で応答を送信するDNSをクエリすると、その後DNS応答MMEに基づいてTCP接続が開始される他の情報がなくなります。

DNSからMMEへ

• MMEはTCP接続後にクエリを送信します
•  DNSはそれを確認応答します。
•  DNSは、フラグが「Message is not truncated」に設定された応答を送信します。これは、DNSと共有されるMSSが9060バイトに設定され、応答全体が1回で送信されるためです。
•  MMEはコンテンツなしでACKで応答します
•  DNSは、ペイロードが4181バイトであるMessage 38のコンテンツにACKを送信します
• MMEは、最後のフラグメントを受信するとすぐに、TCPを送信して接続をリセットし、閉じます。

MMEが2 ～ 3セグメントのペイロード全体、またはDNSからの1回の試行でペイロード全体を受信すると、MMEはTCPリセットメッセージを送信します。

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

テスト シナリオ

1.専用のテストで必要なすべてのデバッグログ/トレースをキャプチャし、サブスクライバが問題のあるAPNを参照するときに同時にログを有効にします 

2.テストシナリオが実行されるたびに、サブスクライバがサブスクライバをフラッシュするために新しい接続を行う必要があることを確認します。

3.テストのために、1つのテスターを割り当て、そのテスターはIMSIを使用して専用のテストを行う必要があり、問題のある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)

トラブルシュート

1.記載されているすべてのコマンドの出力をチェックして、システム内部にパケット廃棄があるかどうかを確認します。

2.統計情報をチェックして、ノードのDNSタイムアウトの頻度が増加していることを確認します。

[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

これらのコマンドを実行して複数の反復に関する統計情報をキャプチャし、クエリタイムアウトが徐々に増えていることを確認した後、Demuxとsessgrsの間でパケット廃棄が行われなかったので、内部システムに問題は発生しません

さらに、DNSの外部接続または設定の問題を確認するには、図に示すように、APNではなくMMEから手動で置換値のクエリを直接実行します。このクエリは遅延なく正しく解決され、外部接続と設定にも問題がないと判断します。

[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

問題はDNSとSGSN-MMEの間にあります。DNSの送信応答はtoponとして表示され、MMEはtoponエントリに対して再度クエリを実行する必要がありますが、手動でクエリ解決を実行しても成功しませんでした

コマンドの出力とトレースによると、APNを照会すると、フラグメント内のTCP接続を介して30個の置換を含む応答が返され、MMEはこれらのフラグメントを確認応答し、DNSにリセットを送信します。

MMEはリセット用にTCPを送信するため、MMEではDNSクエリがクエリタイムアウトとしてエラーを示し、この時点まで、フラグメントが完全に確認応答されず、このプロセスが完了する前に、MMEはTCPを送信します。

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

ログから、最初のタイムアウト後にMMEが次の再試行に対してエラー115を送信したことを示します。これは、最初のTCP接続がソケットで閉じられないためです。  最初のTCP接続のタイムアウトが発生し、前の接続が閉じられませんでした。

新しい接続が開始されます。この接続は、以前の接続が確立されたソケット上にあり、クリアされません。新しい接続が形成されましたが、何らかの理由でソケットが最初のタイムアウト後に以前の接続を閉じなかったにもかかわらず、エラー115（操作が進行中）が表示されます。

解決方法

DNSコンテキストのvpnmgrを再起動します。ソフトウェア修正はまだ提供されていません。