古河電工FITELnet F220 の IPSec VPN でバグを踏む

2023年6月16日 16:11

前回の記事からだいぶ間が空いてしまったが、実は設定中にファームウェアのバグを踏んでしまいベンダーの古河電工のサポート経由で解析してもらっている。問題点はわかったものの、修正ファームは 2023年6月現在出ていないので根本的に解決できていない。

2023年8月1日追記：
新ファームウェア V01.12(00) でこの問題は修正されました

2024年7月18日追記：
この記事で記述した設定内容はさくらクラウドVPCルータバージョン 1 の場合で、バージョン 2 の場合は設定内容が変わります

問題の IPSec VPN

詳細の設定方法についてはバグが修正されてから改めて紹介するので、この記事ではどのような設定が問題になったか、という点だけをかいつまんで紹介する。

IPSec VPN では双方で設定をすり合わせる必要があり、接続先から提供されているのは次のような情報のみ。

ISAKMP SAの寿命
28800
IKEキープアライブ(DPD) インターバル
15
IKEキープアライブ(DPD) タイムアウト
30
IPSEC SAの寿命
1800
暗号アルゴリズム
AES128
ハッシュアルゴリズム
SHA1

その他、設定情報のドキュメントなどから読み取れるのが、IKE v1 のみ、PFS あり、PFS DH は group 2(modp1024)、DPD あり、など。

FITELnet F220 の設定

これに従い、FITELnet F220 に次のような設定を入れ込む。

!
crypto ipsec security-association lifetime seconds 1800
!
crypto ipsec policy VPC1
 set pfs group2
 set security-association always-up
 set security-association lifetime seconds 1800
 set security-association transform esp-aes esp-sha-hmac
 set ip df-bit 0
 set ip fragment post
exit
!
crypto ipsec selector VPC1
 src 1 ipv4 any
 dst 1 ipv4 any
exit
!
crypto isakmp log sa
crypto isakmp log session
crypto isakmp log negotiation-fail
!
crypto isakmp policy VPC1
 authentication pre-share
 encryption aes
 group 2
 lifetime 28800
 hash sha
exit
!
crypto isakmp profile VPC1
 local-address 172.30.128.254
 keepalive interval 15 always-send
 self-identity address 172.30.128.254
 set isakmp-policy VPC1
 set ipsec-policy VPC1
 set peer 27.133.133.133
 ike-version 1
 local-key ThisIsSecret
exit
!
crypto map VPC1 ipsec-isakmp
 match address VPC1
 set isakmp-profile VPC1
exit
!

設定内容的には難しいところはなくて、上記で提供されたとおりに設定しただけという感じだ。

これで IPSec VPN 自体は接続できるようになったものの、先方の VPCサーバのログを見ていると、warning が出力され続ける状況になった。

Jun  9 13:17:42 rt-112700568505 pluto[31401]: packet from 126.100.60.30:500: received Vendor ID payload [Dead Peer Detection]
Jun  9 13:17:42 rt-112700568505 pluto[31401]: "peer-126.100.60.30-tunnel-vti" #5: responding to Main Mode
Jun  9 13:17:42 rt-112700568505 pluto[31401]: "peer-126.100.60.30-tunnel-vti" #5: Peer ID is ID_IPV4_ADDR: '172.30.128.254'
Jun  9 13:17:42 rt-112700568505 pluto[31401]: "peer-126.100.60.30-tunnel-vti" #5: sent MR3, ISAKMP SA established
Jun  9 13:17:42 rt-112700568505 pluto[31401]: "peer-126.100.60.30-tunnel-vti" #5: DPD: R_U_THERE has invalid rcookie (broken Cisco?)
Jun  9 13:17:42 rt-112700568505 pluto[31401]: "peer-126.100.60.30-tunnel-vti" #5: sending encrypted notification INVALID_COOKIE to 126.100.60.30:500

これは接続を維持するための DPD(Dead Peer Detection)で FITELnet F220 から送られるパケットの内部になんらかの不整合があり、これを VPCサーバ側が認識して warning を返す状態になっている。なお、本来の意味での DPD としては動作していないものの、一定のタイミングでパケットを送り続ける状態になるため、VPN の接続自体は維持される。

この状態で show crypt isakmp statistics を確認すると、

#show crypto isakmp statistics

================= INFO RECV =================

--------------- IKEv1/v2 ----------------
Total received packet     : 132
[Discard Packet]
  Peer is locked out                   : 0(D)
  Internal connection error            : 0(D)
  Unsupported IKE version              : 0(D)
  Invalid IP Address                   : 0(D)
  Invalid ISAKMP Header                : 0(D)
  Local address has been invalid       : 0(D)
  IKE major version has been changed   : 0(D)
  On crypto isakmp discard             : 0(D)

---------------- IKEv1 ------------------
[Exchange Type]
Base Exchange                : 0(D)
Identity Protection Exchange : 84
Authentication Only Exchange : 0(D)
Aggressive Exchange          : 0
Informational Exchange       : 28
Configuration Exchange       : 0
Quick Mode Exchange          : 20
New group Exchange           : 0(D)
Other Exchange               : 0(D)
[Discard Packet]
Invalid exchange type                    : 0(D)
Invalid cookie                           : 19(D)
Negotiation wasn't allowed               : 0(D)
P1 is being deleted                      : 0(D)
Waiting for IKE processing               : 0(D)
Retransmit not requiring response        : 0(D)
On retry-guard                           : 0(D)
500-port request after NAT detection     : 0(D)
4500-port request after no-NAT detection : 0(D)
Address or port number has been changed  : 0(D)
Phase-2 packet before Phase-1            : 0(D)
Packet during DH calculation             : 0(D)
Decode error                             : 0(D)

Invalid cookie の数字が上がっていく様子がわかる。

DPD を ICMP-DPD に変える

DPD にはもうひとつ、ICMP-DPD というものもあり、こちらに設定を変えてみる。

crypto isakmp profile VPC1
 no keepalive
 keepalive-icmp interval 15 retry 5 retransmit 5 always-send
exit

こちらを流し込んで、ipsec disconnect 1、ipsec connect 1 で再接続を行う。

先程の DPD はパケットが送られないため warning が消えるが、今度は、

Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: initiating Main Mode
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: received Vendor ID payload [XAUTH]
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: received Vendor ID payload [Dead Peer Detection]
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring Vendor ID payload [12f5f28c457168a9702d9fe274cc02d4]
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Peer ID is ID_IPV4_ADDR: '172.30.128.254'
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ISAKMP SA established
Jun  1 17:46:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:46:17 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x58c36f1f)
Jun  1 17:46:37 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x58c36f1f)
Jun  1 17:47:17 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:47:27 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x6e2f46e8)
Jun  1 17:47:47 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x6e2f46e8)
Jun  1 17:48:27 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:48:37 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x77dcacab)
Jun  1 17:48:57 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x77dcacab)
Jun  1 17:49:37 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:49:47 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x8b12bef9)
Jun  1 17:50:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x8b12bef9)
Jun  1 17:50:47 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:50:57 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0xc38a6794)
Jun  1 17:51:17 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0xc38a6794)
Jun  1 17:51:57 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:52:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x6fef4aba)
Jun  1 17:52:27 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0x6fef4aba)
Jun  1 17:53:07 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: ignoring informational payload, type NO_PROPOSAL_CHOSEN
Jun  1 17:53:17 rt-112700568505 pluto[713]: "peer-126.100.60.30-tunnel-vti" #1: Informational Exchange message is invalid because it has a previously used Message ID (0xe7ba3cf0)

このような別の warning が出続ける状態になる。

show crypt statistics の結果を見ると、

#show crypto statistics policy-manager ike-version 1

 Policy-manager Counters
 Last clearing of "show crypto statistics policy-manager" counters 17:46:28 2023/06/01

IKEv1
  PHASE1
    active : 0
    succeeded/failed : 1/0
    retry : 0/0
  XAUTH
    active : 0
    succeeded/failed : 0/0
    retry : 0/0
  MODE-CFG
    active : 0
    succeeded/failed : 0/0
    retry : 0/0
  PHASE2
    active : 0
    succeeded/failed : 2/8
    retry : 0/16
  INFORMATIONAL
    DPD
      active : 0
      succeeded/failed : 0/0
      retry : 0
    DELETE
      send/receive : 2/1

IKEv1/IKEv2
  Limit discard Packets : 0
  ICMP-DPD
      active : 0
      succeeded/failed : 48/0
      retry : 0
  NAT-KEEPALIVE
      send/recv : 0/0

  P1   allocation : 1
  P2   allocation : 2
  Peer allocation : 1

ICMP-DPD の succeeded のカウンターが上がっているので、ICMP-DPD 自体は動いているように見える。

ベンダーからの回答

この問題は手に負えないと考え、ベンダーの古河電工のサポートにコンタクトしたところ、show report-all の情報、その他いくつかのパケットのログなどを送って解析してもらったところ、DPD については冒頭で述べたようなファームウェアのバグであることが判明する。

ただし、ICMP-DPD で出ている warning については、VPN設定のパラメータの不一致が原因と考えられるものの、現時点では解決方法が見つかっていない。(ICMP-DPD ではないときには出ない warning なので、VPN設定のパラメータが不一致とは考えにくいが。。。)

show report-all の取得方法

show report-all コマンドを使うと、デバッグに必要な情報を得ることができる。ただし、telnet/ssh で接続していると情報が膨大なため(6MB とかある)コンソールの内容を保存する必要がある。

tera term の場合、File -> Log というメニューでコンソールの内容をテキストファイルに保存する機能があるので、これを使う。

古河電工のサポートについて

上記問題が手に追えなくなり、サポートにコンタクトしたのが 2023年5月23日。すぐに技術担当者から返答があり、データのやりとり、解析などを行って、ファームウェアのバグであることが判明したのが 6月15日。

やりとりは非常にスムースで、指摘についても的確で、ファームウェアのバグという比較的わかりにくいところに原因があった割に、すぐに原因がわかったのは高度な技術力を持っていることがわかる。

購入したばかりというのもあるが、保守契約などがない状態ですぐサポートを受け付けてもらえるのはとても運用で助かる。

なお、本問題について根本的に解決した折には、設定などは改めて詳しく紹介する。

余談だが、Google Domain を使った Dynamic DNS の設定を紹介しようと記事を書いていたところ、本日(2023年6月16日)、Google から Google Domain のサービス終了と他社への移管が発表され、記事はお蔵入りとなった。