IKEv2を使用したvEdgeでのサービストンネルのIPsec問題のトラブルシューティング

CLIでは、指定したパスの現在のログ/デバッグ情報を表示することもできます。

monitor start /var/log/messages

IPSec問題のトラブルシューティングプロセスを開始するためのヒント

3つの異なるIPsecシナリオを分離できます。症状を特定するには、より良いアプローチを持って始める方法を知ることが良い参照ポイントです。

1. IPsecトンネルが確立されない。
2. IPSecトンネルがダウンし、自身で再確立されました。（フラップ）
3. IPSecトンネルがダウンし、ダウン状態のままになる。

IPSecトンネルが症状を確立しない場合は、IKEネゴシエーションの現在の動作を確認するために、リアルタイムでデバッグする必要があります。

IPSecトンネルがダウンして、それ自体の症状で再確立した場合は、最も一般的にトンネルフラップと呼ばれ、根本原因分析(RCA)が必要です。トンネルがダウンした場合のタイムスタンプを知ることも、デバッグを確認する推定時間を持つことも不可欠です。

IPSecトンネルがダウンし、ダウン状態の症状が続く場合は、トンネルがダウンし、何らかの理由でトンネルがダウンした場合に、ティアダウンの理由と、トンネルが正常に確立されるのを妨げている現在の動作を知る必要があります。

トラブルシューティングを開始する前に、ポイントを特定します。

1. 問題と設定を含むIPsecトンネル（番号）。
2. トンネルがダウンしたときのタイムスタンプ（該当する場合）。
3. IPsecピアのIPアドレス（トンネルの宛先）。

すべてのデバッグとログは/var/log/messagesファイルに保存され、現在のログではmessagesファイルに保存されますが、この特定の症状の場合、フラップは問題の後に数時間または数日で特定できます。関連するデバッグのほとんどはmessages1、2、3..適切なメッセージファイルを確認し、IPsecトンネル関連のIKEネゴシエーションのデバッグ(chaon)を分析するためのタイムスタンプを知ることが重要です。

ほとんどのデバッグでは、IPsecトンネルの番号は出力されません。ネゴシエーションとパケットを識別する最も一般的な方法は、リモートピアのIPアドレスと、トンネルがエッジから送信されるIPアドレスです。IKEデバッグの出力例を次に示します。

Jun 18 00:31:22 vedge01 charon: 09[CFG] vici initiate 'child_IPsec2_1'
Jun 18 00:31:22 vedge01 charon: 16[IKE] initiating IKE_SA ipsec2_1[223798] to 10.10.10.1
Jun 18 00:31:22 vedge01 charon: 16[IKE] initiating IKE_SA ipsec2_1[223798] to 10.10.10.1

Jun 18 00:31:22 vedge01 charon: 09[CFG] vici initiate 'child_ipsec2_1'
Jun 18 00:31:22 vedge01 charon: 16[IKE] initiating IKE_SA ipsec2_1[223798] to 10.10.10.1
Jun 18 00:31:22 vedge01 charon: 16[IKE] initiating IKE_SA ipsec2_1[223798] to 10.10.10.1
Jun 18 00:31:22 vedge01 charon: 16[ENC] generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]
Jun 18 00:31:22 vedge01 charon: 16[NET] sending packet: from 10.132.3.92[500] to 10.10.10.1[500] (464 bytes)
Jun 18 00:31:22 vedge01 charon: 12[NET] received packet: from 10.10.10.1[500] to 10.132.3.92[500] (468 bytes)
Jun 18 00:31:22 vedge01 charon: 12[ENC] parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(HTTP_CERT_LOOK) N(FRAG_SUP) V ]
Jun 18 00:31:22 vedge01 charon: 12[ENC] received unknown vendor ID: 4f:85:58:17:1d:21:a0:8d:69:cb:5f:60:9b:3c:06:00
Jun 18 00:31:22 vedge01 charon: 12[IKE] local host is behind NAT, sending keep alives

interface ipsec2
  ip address 192.168.1.9/30
  tunnel-source      10.132.3.92
  tunnel-destination 10.10.10.1
  dead-peer-detection interval 30
  ike
   version      2
   rekey        86400
   cipher-suite aes256-cbc-sha1
   group        14
   authentication-type
    pre-shared-key
     pre-shared-secret $8$wgrs/Cw6tX0na34yF4Fga0B62mGBpHFdOzFaRmoYfnBioWVO3s3efFPBbkaZqvoN
    !
   !
  !
  ipsec
   rekey                   3600
   replay-window           512
   cipher-suite            aes256-gcm
   perfect-forward-secrecy group-14
  !

現象1.  IPsecトンネルが確立されない

この問題はトンネルの最初の実装である可能性があるため、まだアップ状態ではなく、IKEデバッグが最適なオプションです。

Jun 18 00:31:17 vedge01 FTMD[1472]: %Viptela-vedge01-FTMD-6-INFO-1000001: VPN 1 Interface ipsec2 DOWN
Jun 18 00:31:17 vedge01 FTMD[1472]: %Viptela-vedge01-ftmd-6-INFO-1400002: Notification: interface-state-change severity-level:major host-name:"vedge01" system-ip:4.0.5.1 vpn-id:1 if-name:"ipsec2" new-state:down 

Jun 18 00:31:17 vedge01 charon: 11[IKE] giving up after 3 retransmits

Jun 18 00:28:22 vedge01 charon: 08[IKE] retransmit 3 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:28:22 vedge01 charon: 08[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes)  

Jun 18 00:26:45 vedge01 charon: 06[IKE] retransmit 2 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:26:45 vedge01 charon: 06[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 

Jun 18 00:25:21 vedge01 charon: 08[IKE] sending DPD request 
Jun 18 00:25:21 vedge01 charon: 08[ENC] generating INFORMATIONAL request 543 [ ] 
Jun 18 00:25:21 vedge01 charon: 08[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 
Jun 18 00:25:51 vedge01 charon: 05[IKE] retransmit 1 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:25:51 vedge01 charon: 05[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes)

最後に成功したDPDパケット交換は、要求# 542として記述されます。

Jun 18 00:24:08 vedge01 charon: 11[ENC] generating INFORMATIONAL request 542 [ ] 
Jun 18 00:24:08 vedge01 charon: 11[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 
Jun 18 00:24:08 vedge01 charon: 07[NET] received packet: from 13.51.17.190[4500] to 10.10.10.1[4500] (76 bytes) 
Jun 18 00:24:08 vedge01 charon: 07[ENC] parsed INFORMATIONAL response 542 [ ] 

 ステップ2：すべての情報を正しい順序に並べます。

Jun 18 00:24:08 vedge01 charon: 11[ENC] generating INFORMATIONAL request 542 [ ] 
Jun 18 00:24:08 vedge01 charon: 11[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 
Jun 18 00:24:08 vedge01 charon: 07[NET] received packet: from 10.10.10.1[4500] to 10.132.3.92[4500] (76 bytes) 
Jun 18 00:24:08 vedge01 charon: 07[ENC] parsed INFORMATIONAL response 542 [ ] 

Jun 18 00:25:21 vedge01 charon: 08[IKE] sending DPD request 
Jun 18 00:25:21 vedge01 charon: 08[ENC] generating INFORMATIONAL request 543 [ ] 
Jun 18 00:25:21 vedge01 charon: 08[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 
Jun 18 00:25:51 vedge01 charon: 05[IKE] retransmit 1 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:25:51 vedge01 charon: 05[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes)

Jun 18 00:26:45 vedge01 charon: 06[IKE] retransmit 2 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:26:45 vedge01 charon: 06[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 

Jun 18 00:28:22 vedge01 charon: 08[IKE] retransmit 3 of request with message ID 543 (tries=3, timeout=30, exchange=37, state=2) 
Jun 18 00:28:22 Lvedge01 charon: 08[NET] sending packet: from 10.132.3.92[4500] to 10.10.10.1[4500] (76 bytes) 

Jun 18 00:31:17 vedge01 charon: 11[IKE] giving up after 3 retransmits
Jun 18 00:31:17 vedge01 FTMD[1472]: %Viptela-LONDSR01-FTMD-6-INFO-1000001: VPN 1 Interface ipsec2 DOWN
Jun 18 00:31:17 vedge01 FTMD[1472]: %Viptela-LONDSR01-ftmd-6-INFO-1400002: Notification: interface-state-change severity-level:major host-name:"LONDSR01" system-ip:4.0.5.1 vpn-id:1 if-name:"ipsec2" new-state:down 

上記の例では、vEdge01が10.10.10.1からのDPDパケットを受信しないため、トンネルがダウンしています。これは、3つのDPD再送信後にIPsecピアが「lost」に設定され、トンネルがダウンすると予想されます。この動作には複数の理由があります。通常、これはパケットがパスで損失またはドロップされるISPに関連しています。問題が一度発生した場合、失われたトラフィックを追跡する方法はありませんが、問題が解決しない場合は、vEdge、リモートIPSecピア、およびISPのキャプチャを使用してパケットを追跡できます。

症状3:IPsecトンネルがダウンし、ダウン状態のままになる

この症状で前述したように、トンネルは正常に動作していましたが、何らかの理由でダウンし、トンネルが正常に確立されませんでした。このシナリオでは、ネットワークに影響があります。

トラブルシューティングを開始する前に、ポイントを特定します。

1. 問題と設定を含むIPsecトンネル（番号）。
2. トンネルがダウンしたときのタイムスタンプ。
3. IPsecピアのIPアドレス（トンネルの宛先）

PFSの不一致

この例では、トンネルがダウンしたときにタイムスタンプでトラブルシューティングが開始されません。問題が解決しない限り、IKEデバッグが最適なオプションです。 

interface ipsec1
  description             VWAN_VPN
  ip address 192.168.0.101/30
  tunnel-source-interface ge0/0
  tunnel-destination      10.10.10.1
  ike
   version      2
   rekey        28800
   cipher-suite aes256-cbc-sha1
   group        2
   authentication-type
    pre-shared-key
     pre-shared-secret "$8$njK2pLLjgKWNQu0KecNtY3+fo3hbTs0/7iJy6unNtersmCGjGB38kIPjsoqqXZdVmtizLu79\naQdjt2POM242Yw=="
    !
   !
  !
  ipsec
   rekey                   3600
   replay-window           512
   cipher-suite            aes256-cbc-sha1
   perfect-forward-secrecy group-16 
  !
  mtu                     1400
  no shutdown

デバッグリンクが有効になり、ネゴシエーションが表示されます。

daemon.info: Apr 27 05:12:56 vedge01 charon: 16[NET] received packet: from 10.10.10.1[4500] to 172.28.0.36[4500] (508 bytes) 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[ENC] parsed CREATE_CHILD_SA request 557 [ SA No TSi TSr ] 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[CFG] received proposals: ESP:AES_GCM_16_256/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA2_256_128/NO_EXT_SEQ 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_4096/NO_EXT_SEQ 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[IKE] no acceptable proposal found 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[IKE] failed to establish CHILD_SA, keeping IKE_SA 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[ENC] generating CREATE_CHILD_SA response 557 [ N(NO_PROP) ] 
daemon.info: Apr 27 05:12:56 vedge01 charon: 16[NET] sending packet: from 172.28.0.36[4500] to 10.10.10.1[4500] (76 bytes) 

daemon.info: Apr 27 05:12:57 vedge01 charon: 08[NET] received packet: from 10.10.10.1[4500] to 172.28.0.36[4500] (76 bytes) 
daemon.info: Apr 27 05:12:57 vedge01 charon: 08[ENC] parsed INFORMATIONAL request 558 [ ] 
daemon.info: Apr 27 05:12:57 vedge01 charon: 08[ENC] generating INFORMATIONAL response 558 [ ] 
daemon.info: Apr 27 05:12:57 vedge01 charon: 08[NET] sending packet: from 172.28.0.36[4500] to 10.10.10.1[4500] (76 bytes) 
daemon.info: Apr 27 05:12:58 vedge01 charon: 07[NET] received packet: from 10.10.10.1[4500] to 172.28.0.36[4500] (396 bytes) 
daemon.info: Apr 27 05:12:58 vedge01 charon: 07[ENC] parsed CREATE_CHILD_SA request 559 [ SA No TSi TSr ] 
daemon.info: Apr 27 05:12:58 vedge01 charon: 07[CFG] received proposals: ESP:AES_GCM_16_256/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ, ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ, ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ, ESP:3DES_CBC/HMAC_SHA2_256_128/NO_EXT_SEQ 
daemon.info: Apr 27 05:12:58 vedge01 charon: 07[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_4096/NO_EXT_SEQ 
daemon.info: Apr 27 05:12:58 Avedge01 charon: 07[IKE] no acceptable proposal found 
daemon.info: Apr 27 05:12:58 vedge01 charon: 07[IKE] failed to establish CHILD_SA, keeping IKE_SA 

注：  CREATE_CHILD_SAパケットは、キー再生成または新しいSAごとに交換されます。詳細については、「IKEv2パケット交換について」を参照してください

IKEデバッグは同じ動作を示し、常に繰り返されるため、情報の一部を取得して分析することができます。 

CREATE_CHILD_SAは、新しいSPISを生成してIPsecエンドポイント間で交換する目的を持つキー再生成を意味します。

• エッジは、10.10.10.1からCREATE_CHILD_SA要求パケットを受信します。
• エッジは要求を処理し、ピア10.10.10.1から送信されたプロポーザル(SA)を確認します
• エッジは、ピアから送信された受信したプロポーザルと、設定されたプロポーザルを比較します。
• 交換されたCREATE_CHILD_SAが「no acceptable proposal found」で失敗します。

この時点で、次のような問題が発生します。トンネルが以前に動作していて、変更が行われていなかった場合、設定の不一致があるのはなぜですか。

深く分析すると、ピアが送信していない設定済みのプロポーザルに追加フィールドがあります。

設定されたプロポーザル：ESP:AES_CBC_256/HMAC_SHA1_96/MODP_4096/NO_EXT_SEQ

受け取った提案：
ESP:AES_GCM_16_256/NO_EXT_SEQ、
ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ、
ESP:3DES_CBC/HMAC_SHA1_96/NO_EXT_SEQ,
ESP:AES_CBC_256/HMAC_SHA2_256_128/NO_EXT_SEQ、
ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ、
ESP:3DES_CBC/HMAC_SHA2_256_128/NO_EXT_SEQ

MODP_4096は、フェーズ2（IPsecセクション）のPFS(Perfect-forward-secrecy)に対してvedgeが設定されているDHグループ16です。

PFSは、トンネルが正常に確立できる、またはIKEネゴシエーションの発信側または応答側が誰であるかによって確立できない唯一の不一致の設定です。ただし、キー再生成が開始されると、トンネルは続行できず、この症状が発生したり、関連する可能性があります。

DELETEイベントが原因で切断された後にvEdge IPSec/Ikev2トンネルが再始動しない

この動作の詳細については、Cisco Bug ID CSCvx86427を参照してください。

この問題が発生すると、IKEデバッグが最適なオプションになります。ただし、デバッグが有効になっている場合、この特定の不具合に関して、ターミナルとメッセージファイルのどちらにも情報が表示されません。

この問題を絞り込み、vEdgeがCisco Bug ID CSCvx86427に該当するかどうかを確認するには、トンネルがダウンした瞬間を見つける必要があります。

トラブルシューティングを開始する前に、ポイントを特定します。

1. 問題と設定を含むIPsecトンネル（番号）。
2. トンネルがダウンしたときのタイムスタンプ。
3. IPsecピアのIPアドレス（トンネルの宛先）

タイムスタンプが特定され、時間とログが関連付けられた後、トンネルがダウンする直前のログを確認します。

Apr 13 22:05:21 vedge01 charon: 12[IKE] received DELETE for IKE_SA ipsec1_1[217] 
Apr 13 22:05:21 vedge01 charon: 12[IKE] deleting IKE_SA ipsec1_1[217] between 10.16.0.5[10.16.0.5]...10.10.10.1[10.10.10.1] 
Apr 13 22:05:21 vedge01 charon: 12[IKE] deleting IKE_SA ipsec1_1[217] between 10.16.0.5[10.16.0.5]...10.10.10.1[10.10.10.1] 
Apr 13 22:05:21 vedge01 charon: 12[IKE] IKE_SA deleted 
Apr 13 22:05:21 vedge01 charon: 12[IKE] IKE_SA deleted 
Apr 13 22:05:21 vedge01 charon: 12[ENC] generating INFORMATIONAL response 4586 [ ] 
Apr 13 22:05:21 vedge01 charon: 12[NET] sending packet: from 10.16.0.5[4500] to 10.10.10.1[4500] (80 bytes) 
Apr 13 22:05:21 vedge01 charon: 12[KNL] Deleting SAD entry with SPI 00000e77 
Apr 13 22:05:21 vedge01 FTMD[1269]: %Viptela-AZGDSR01-FTMD-6-INFO-1000001: VPN 1 Interface ipsec1 DOWN
Apr 13 22:05:21 vedge01 FTMD[1269]: %Viptela-AZGDSR01-ftmd-6-INFO-1400002: Notification: interface-state-change severity-level:major host-name:"vedge01" system-ip:4.1.0.1 vpn-id:1 if-name:"ipsec1" new-state:down 

注：  IPSecネゴシエーションには複数のDELETEパケットがあり、CHILD_SAのDELETEはREKEYプロセスに対して予期されるDELETEです。この問題は、純粋なIKE_SA DELETEパケットが特定のIPSecネゴシエーションなしで受信された時にに発生します。このDELETEによって、すべてのIPsec/IKEトンネルが削除されます。

関連情報

• KEv2パケット交換およびプロトコルレベルデバッグ
• インターネットキー交換(IKE):RFC 2409
• IKEv2:RFC 7296
• vEdgeとCisco IOS間のサイト間LAN間IPSec
• テクニカル サポートとドキュメント – Cisco Systems