Invalid SPI の発生原因および調査方法について

Shinpei Kono · ‎2015-03-14

はじめに

本資料では、IPsec が稼動するIOSルータで検知される Invalid SPI に関して説明、および対処方法を紹介します。

Invalid SPI というのは以下のログのことを指しています。

%CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0x410F2223(1091510819), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0

これは 14.14.14.14 のVPNルータから IPsec パケットを受信した際に、受信したルータが、当該パケットの ESP header に含まれる SPI の値を持つ IPsec SA を保持していなかったことを検知したものです。つまり、VPNを終端するルータ間で IPsec SA の不一致が生じていることを示しており、受信ルータはこのようなパケットを復号できずに破棄します。

以下では、このメッセージが発生する契機を具体的にイメージいただくため、まずは意図的にメッセージを再現させて説明します。

再現手順

以降のログやデバッグの出力を照合するにあたり、以下の簡易構成図をご参照ください。

初期状態では Router1、Router2 の間で IPsec SA が確立しており、SPI が一致しています。

Router1#show crypto ipsec sa | i spi
     current outbound spi: 0xAEE791CF(2934411727)
      spi: 0x17232DF3(388181491)
      spi: 0xAEE791CF(2934411727)
     
Router2#show crypto ipsec sa | i spi
     current outbound spi: 0x17232DF3(388181491)
      spi: 0xAEE791CF(2934411727)
      spi: 0x17232DF3(388181491)

Router1#show crypto ipsec spi-lookup
Active SPI table
     SPI Prot Local Address            M Type
17232DF3 ESP  14.14.14.14             * ?

Router2#show crypto ipsec spi-lookup
Active SPI table
     SPI Prot Local Address            M Type
AEE791CF ESP  11.11.11.11             * ?

Router1 配下のホストから 2Mbps のトラフィックを印加しているため、Router2 は ESPパケットを受信し続けています。

Router#show crypto engine connections active
Crypto Engine Connections

   ID  Type    Algorithm           Encrypt  Decrypt LastSeqN IP-Address
   81  IPsec   AES+SHA                   0        0        0 14.14.14.14
   82  IPsec   AES+SHA              377512        0        0 14.14.14.14
 2007  IKE     SHA+AES256                0        0        0 14.14.14.14

Router2#show crypto engine connections active
Crypto Engine Connections

   ID  Type    Algorithm           Encrypt  Decrypt LastSeqN IP-Address
 1006  IKE     SHA+AES256                0        0        0 11.11.11.11
 2045  IPsec   AES+SHA                   0   385142        0 11.11.11.11
 2046  IPsec   AES+SHA                   0        0        0 11.11.11.11

ここで意図的に Router2 の IKE (ISAKMP) SA を削除します。

Router2#clear crypto isakmp 1006
Router2#show crypto engine connections active
Crypto Engine Connections

   ID  Type    Algorithm           Encrypt  Decrypt LastSeqN IP-Address
 2045  IPsec   AES+SHA                   0   515519        0 11.11.11.11
 2046  IPsec   AES+SHA                   0        0        0 11.11.11.11

次にRouter2 の IPsec SA を削除します。
IKE (ISAKMP) SA を削除しているため、IPsec SA が削除されても、Router1(14.14.14.14) に対しては何の Notification も飛びません。そのため、Router1 は IPsec SA を維持して、SPI = AEE791CF を ESP header に含んだパケットを送出し続けます。

Router2 では、この SPI が削除されているため、即座に Invalid SPI が検知されます。

Router2#clear crypto sa peer 14.14.14.14
Router2#
Router2#
Mar 13 14:33:47.723: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0xF532E327(4113752871), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0

なお、再現方法は、経路上のスイッチのポートを閉塞した状態から、Router2 で IPsec/IKE SA を削除して、スイッチのポートを再度開放することにより、Router1 の IKE SA は残して Invalid SPI を発生させる等、いろいろなパターンを試すことが可能です。

発生時の影響

極めて一過的なステータスである場合もあるため、Invalid SPI によりどのくらいの実影響が発生していたかを推し量ることは困難です。強いて数値で確認する方法を挙げると、show crypto datapath ipv4 snapshot non-zero の出力結果を Invalid SPI の発生前後で実行する方法が考えられます。

以下は、先ほどと同じ手順で Invalid SPI を発生させて、どのくらいのパケットが Invalid SPI として検知されているかを確認した結果になります。

Router2#show crypto datapath ipv4 snapshot non-zero | i invalid spi
invalid spi:                       81
Router2#
Router2#
Router2#clear crypto sa peer 14.14.14.14
Router2#
Mar 13 13:13:59.819: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to down
Mar 13 13:13:59.819: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0x71C4E478(1908728952), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0
Mar 13 13:13:59.823: %CRYPTO-5-SESSION_STATUS: Crypto tunnel is DOWN.  Peer 14.14.14.14:500       Id: 14.14.14.14
Router2#
Router2#
Mar 13 13:14:20.587: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to up
Mar 13 13:14:20.591: %CRYPTO-5-SESSION_STATUS: Crypto tunnel is UP  .  Peer 14.14.14.14:500       Id: 14.14.14.14
Router2#
Router2#
Router2#show crypto datapath ipv4 snapshot non-zero | i invalid spi
invalid spi:                      430
Router2#

原因調査方法

意図的なオペレーションにより再現させることはできました。それでは、通常運用中にどのように本メッセージが発生しうるかというと、SA の不一致状態が生じる原因は無数にあり、
お問い合わせを頂戴してもすべての原因を網羅的にお伝えすることは困難です。

Invalid SPI がかなりの高頻度で発生し、看過できない状態となっている場合には、原因調査のため以下のデバッグを両端のルータに仕掛けて事象再現を待つ必要があります。

Router2#debug crypto isakmp
Crypto ISAKMP debugging is on
Router2#debug crypto ipsec
Crypto IPSEC debugging is on

!--- こちらは最低限必要なデバッグとなります。
!--- 代理店やメーカのサポート担当者から上記以外のデバッグを追加で依頼される場合もあります。

デバッグの目的は、一方のルータでSA の削除が発生するまでのトリガとなるイベントを把握するためとなり、Invalid SPI の原因調査ではほぼ必須の情報となります。デバッグ採取に際しては、負荷上昇を抑えるための一般的な対処にご留意ください。

(参考) debug 取得と logging buffer のサイズについて
https://supportforums.cisco.com/ja/document/50256

以下は、先ほどの再現手順でのデバッグ出力例となりますが、すでに IKE(ISAKMP) SA がなく、IPsec SA が削除されるイベントが分かるのみとなり、あまり有意的な出力は得られていません。しかし原因不明の Invalid SPI の調査では非常に重要な出力が得られることが見込まれます。

Router2#clear crypto sa peer 14.14.14.14

Mar 13 11:13:18.587:  ISAKMP: Failed to find peer index node to update peer_info_list
Mar 13 11:13:18.587: IPSEC(update_current_outbound_sa): updated peer 14.14.14.14 current outbound sa to SPI A3F09B0
Mar 13 11:13:18.587: IPSEC(delete_sa): deleting SA,
  (sa) sa_dest= 11.11.11.11, sa_proto= 50,
    sa_spi= 0x8535A820(2234886176),
    sa_trans= esp-aes esp-sha-hmac , sa_conn_id= 2047
    sa_lifetime(k/sec)= (4608000/3600),
  (identity) local= 11.11.11.11:0, remote= 14.14.14.14:0,
    local_proxy= 0.0.0.0/0.0.0.0/256/0,
    remote_proxy= 0.0.0.0/0.0.0.0/256/0
Mar 13 11:13:18.587: IPSEC(update_current_outbound_sa): updated peer 14.14.14.14 current outbound sa to SPI A3F09B0
Mar 13 11:13:18.587: IPSEC(delete_sa): deleting SA,
  (sa) sa_dest= 14.14.14.14, sa_proto= 50,
    sa_spi= 0xA3F09B0(171903408),
    sa_trans= esp-aes esp-sha-hmac , sa_conn_id= 2048
    sa_lifetime(k/sec)= (4608000/3600),
  (identity) local= 11.11.11.11:0, remote= 14.14.14.14:0,
    local_proxy= 0.0.0.0/0.0.0.0/256/0,
    remote_proxy= 0.0.0.0/0.0.0.0/256/0
Mar 13 11:13:18.587: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0x8535A820(2234886176), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0
Mar 13 11:13:18.591: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to down

Invalid SPI Recovery

Invalid SPI が発生すると、再度両端のルータで同一の SPI の IPsec SA が生成され、通信が復旧するまでに時間を要する場合があります。 Invalid SPI Recovery というフィーチャーを使用することにより、復旧までの時間が短縮されることが見込まれます。

Command Refernce より

Usage Guidelines
This command allows you to configure your router so that when an invalid security parameter index error (shown as “Invalid SPI”) occurs, an IKE SA is initiated. The “IKE” module, which serves as a checkpoint in the IPSec session, recognizes the “Invalid SPI” situation. The IKE module then sends an “Invalid Error” message to the packet-receiving peer so that synchronization of the security association databases (SADBs) of the two peers can be attempted. As soon as the SADBs are resynchronized, packets are no longer dropped.

たとえば、Router2 が Invalid SPI を検知した場合に、IKE(ISAKMP) SA が存在する場合であれば、Router2 は DELETE Notification をピアの Router1 に送出し、そのまま新規で IPsec SA の再生成が行われます。

しかし、IKE（ISAKMP）SA が存在しない場合には、Router1 は Router2 に IPsec SA が削除されており、通信不可であることを検知できないため再生成が速やかに行われません。

以下の設定を実施すると、Router2 で Invalid SPI を検知して、かつ Router2 に IKE(ISAKMP) SA が存在しない場合に、Router は、Router1 と即座に IKE SA を生成するためのネゴシエーションを開始します。　その結果、Router1 で不要な IPsec SA が削除され、IKE、IPsec SA が速やかに一致するような動作になります。

 Router2(config)#crypto isakmp invalid-spi-recovery

crypto isakmp invalid-spi-recovery を設定して、再現テストをした場合

Router2#clear crypto sa peer 14.14.14.14

Mar 13 14:00:21.887:  ISAKMP: Failed to find peer index node to update peer_info_list
Mar 13 14:00:21.891: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to down
Mar 13 14:00:21.891: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0x42060745(1107691333), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0
Mar 13 14:00:21.891: ISAKMP:(0): SA request profile is SHKONO
Mar 13 14:00:21.891: ISAKMP: Found a peer struct for 14.14.14.14, peer port 500
Mar 13 14:00:21.891: ISAKMP: Locking peer struct 0x31DEB8B8, refcount 1 for ike_initiate_sa_for_inv_spi_recovery
!--- Invalid SPI Recovery が発動。
Mar 13 14:00:21.891: ISAKMP: local port 500, remote port 500
Mar 13 14:00:21.891: ISAKMP:(0):Found ADDRESS key in keyring SHKONO
Mar 13 14:00:21.891: ISAKMP:(0): Unknown DOI 0
Mar 13 14:00:21.891: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
Mar 13 14:00:21.891: ISAKMP:(0): constructed NAT-T vendor-07 ID
Mar 13 14:00:21.891: ISAKMP:(0): constructed NAT-T vendor-03 ID
Mar 13 14:00:21.895: ISAKMP:(0): constructed NAT-T vendor-02 ID
Mar 13 14:00:21.895: ISAKMP : beginning Main Mode exchange for INV SPI RECOV
Mar 13 14:00:21.895: ISAKMP:(0): sending packet to 14.14.14.14 my_port 500 peer_port 500 (I) MM_NO_STATE
Mar 13 14:00:21.895: ISAKMP:(0):Sending an IKE IPv4 Packet.
!--- そのまま Main Mode 開始
(中略)
Mar 13 14:00:22.027: ISAKMP:(1008):Send initial contact
Mar 13 14:00:22.027: ISAKMP:(1008):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
Mar 13 14:00:22.031: ISAKMP (1008): ID payload
        next-payload : 8
        type         : 1
        address      : 11.11.11.11
        protocol     : 17
        port         : 500
        length       : 12
Mar 13 14:00:22.031: ISAKMP:(1008):Total payload length: 12
Mar 13 14:00:22.031: ISAKMP:(1008): sending packet to 14.14.14.14 my_port 500 peer_port 500 (I) MM_KEY_EXCH
Mar 13 14:00:22.031: ISAKMP:(1008):Sending an IKE IPv4 Packet.
Mar 13 14:00:22.031: ISAKMP:(1008):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
Mar 13 14:00:22.031: ISAKMP:(1008):Old State = IKE_I_MM4  New State = IKE_I_MM5
!--- MM5 の Initial Contact を送出

Router1#
Mar 13 14:00:22.271: ISAKMP (2009): received packet from 11.11.11.11 dport 500 sport 500 Global (R) MM_KEY_EXCH
Mar 13 14:00:22.271: ISAKMP:(2009):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
Mar 13 14:00:22.271: ISAKMP:(2009):Old State = IKE_R_MM4  New State = IKE_R_MM5
Mar 13 14:00:22.271: ISAKMP:(2009): processing ID payload. message ID = 0
Mar 13 14:00:22.271: ISAKMP (2009): ID payload
        next-payload : 8
        type         : 1
        address      : 11.11.11.11
        protocol     : 17
        port         : 500
        length       : 12
Mar 13 14:00:22.275: ISAKMP:(0):: peer matches ISAKMP1 profile
Mar 13 14:00:22.275: ISAKMP:(2009):Found ADDRESS key in keyring KEY
Mar 13 14:00:22.275: ISAKMP:(2009): processing HASH payload. message ID = 0
Mar 13 14:00:22.275: ISAKMP:(2009): processing NOTIFY INITIAL_CONTACT protocol 1
        spi 0, message ID = 0, sa = 0x8C3E1F50
Mar 13 14:00:22.275: ISAKMP:(2009):SA authentication status:
        authenticated
Mar 13 14:00:22.275: ISAKMP:(2009):SA has been authenticated with 11.11.11.11
Mar 13 14:00:22.275: ISAKMP:(2009):SA authentication status:
        authenticated
Mar 13 14:00:22.275: ISAKMP:(2009): Process initial contact,
bring down existing phase 1 and 2 SA's with local 14.14.14.14 remote 11.11.11.11 remote port 500
Mar 13 14:00:22.275: ISAKMP:(2009):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
Mar 13 14:00:22.275: ISAKMP:(2009):Old State = IKE_R_MM5  New State = IKE_R_MM5
Mar 13 14:00:22.279: IPSEC(key_engine): got a queue event with 1 KMI message(s)
Mar 13 14:00:22.279: Delete IPsec SA by IC, local 14.14.14.14 remote 11.11.11.11 peer port 500
(中略)
Mar 13 14:00:22.283: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to down
!--- Router1 は Initial Contact で既存の IPsec SA を削除

crypto isakmp invalid-spi-recovery を設定していない場合には、IKE(ISAKMP)SAがすぐに生成されません。

Router2#clear crypto sa peer  14.14.14.14

Mar 13 14:25:48.067:  ISAKMP: Failed to find peer index node to update peer_info_list
Mar 13 14:25:48.067: %LINEPROTO-5-UPDOWN: Line protocol on Interface Tunnel0, changed state to down
Mar 13 14:25:48.067: %CRYPTO-4-RECVD_PKT_INV_SPI: decaps: rec'd IPSEC packet has invalid spi for destaddr=11.11.11.11, prot=50, spi=0x793CC880(2034026624), srcaddr=14.14.14.14, input interface=GigabitEthernet0/0
Mar 13 14:25:48.071: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:25:48.071: %CRYPTO-5-SESSION_STATUS: Crypto tunnel is DOWN.  Peer 14.14.14.14:500       Id: 14.14.14.14
Mar 13 14:25:48.071: ISAKMP: Deleting peer node by peer_reap for 14.14.14.14: 31DEB8B8
Mar 13 14:25:48.071: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:25:53.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:25:58.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:26:03.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:26:08.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:26:10.887: ISAKMP:(1009):purging SA., sa=29623588, delme=29623588
Mar 13 14:26:13.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880
Mar 13 14:26:18.067: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 11.11.11.11 dst 14.14.14.14 for SPI 0x793CC880 
!--- Router2 はすぐには IKE(ISAKMP) SA のネゴシエーションを開始しようとしない

本資料は sVTI 環境をベースに作成していますが、トラブルシュートの方法についてはIPsec 環境であれば、概ね同一であるとご認識ください。

参考資料

IPsec Troubleshooting: Understanding and Using debug Commands - IPsec Packet has Invalid SPI
http://www.cisco.com/c/en/us/support/docs/security-vpn/ipsec-negotiation-ike-protocols/5409-ipsec-debug-00.html#invalidspi
Cisco IOS セキュリティコンフィギュレーションガイド Invalid Security Parameter Index Recovery
http://www.cisco.com/cisco/web/support/JP/docs/CIAN/IOS/IOS15_1M_T/CG/002/sec_invald_index_rec.html?bid=0900e4b1825298b8
IPsec %RECVD_PKT_INV_SPI Errors and Invalid SPI Recovery Feature Information
http://www.cisco.com/c/en/us/support/docs/security-vpn/ipsec-negotiation-ike-protocols/115801-technote-iosvpn-00.html
Cisco IOS Security Command Reference - crypto isakmp invalid-spi-recovery
http://www.cisco.com/c/en/us/td/docs/ios-xml/ios/security/a1/sec-a1-cr-book/sec-cr-c4.html#wp1793318592
IPSec のトラブルシューティング：debug コマンドの説明と使用
http://www.cisco.com/cisco/web/support/JP/100/1008/1008513_ipsec-debug-00-j.html#invalidspi
IP Encapsulating Security Payload (ESP)
https://www.ietf.org/rfc/rfc2406.txt