Troubleshooting Tip: Phase1 is up yet phase2 is down after IKE rekey or tunnel flap

[nithincs]

Description	This article explains the scenario in which phase 2 of site-to-site VPN between FortiGate tunnels goes down and will not automatically come up.
Scope	FortiGate.
Solution	This behavior is expected when phase 2 'auto-negotiate' is kept disabled at both the VPN peers. The default 'auto-negotiate' is set to disable, and hence, when a tunnel is created from the CLI, it needs to be set to enable manually. HO----IPSEC tunnel---SPOKE. HO Config: config vpn ipsec phase1-interface     edit "SPOKE"         set interface "port2"         set keylife 600         set peertype any         set net-device disable         set proposal aes128-sha256         set comments "VPN: SPOKE (Created by VPN wizard)"         set dhgrp 14         set remote-gw 10.40.19.18         set psksecret ENC     next end config vpn ipsec phase2-interface     edit "SPOKE"         set phase1name "SPOKE"         set proposal aes128-sha256         set dhgrp 14         set keepalive disable         set auto-negotiate disable         set comments "VPN: SPOKE (Created by VPN wizard)"         set src-addr-type name         set dst-addr-type name         set keylifeseconds 300         set src-name "SPOKE_local_subnet_1"         set dst-name "SPOKE_remote_subnet_1"     next end SPOKE config: config vpn ipsec phase1-interface     edit "HUB"         set interface "port1"         set peertype any         set net-device disable         set proposal aes128-sha256         set comments "VPN: HUB (Created by VPN wizard)"         set dhgrp 14         set remote-gw 10.40.51.6         set psksecret ENC     next end config vpn ipsec phase2-interface     edit "HUB"         set phase1name "HUB"         set proposal aes128-sha256         set dhgrp 14         set keepalive disable         set auto-negotiate disable         set comments "VPN: HUB (Created by VPN wizard)"         set src-addr-type name         set dst-addr-type name         set src-name "HUB_local"         set dst-name "HUB_remote"     next end With the above configuration, when IKE rekey happens, it will renew only the IKE SA key and will not bring up the IPsec SA. The behavior is the same when IKE is flushed or Ike is renegotiated. IPsec SA will be time its key life expires. Hub Debug logs: FGT1_HO_TLP # diagnose vpn  ike gateway  list | grep -n life 24:  lifetime/rekey: 600/1 FGT1_HO_TLP # diagnose vpn  ike gateway  list | grep -n life 24:  lifetime/rekey: 600/0 FGT1_HO_TLP # diagnose vpn  ike gateway  list | grep -n life2025-03-27 02:16:19.391914 ike V=root:0:SPOKE:154: initiator: main mode is sending 1st message... 2025-03-27 02:16:19.393222 ike V=root:0:SPOKE:154: cookie 1e0221d336ca7dca/0000000000000000 2025-03-27 02:16:19.394416 ike 0:SPOKE:154: out 2025-03-27 02:16:19.400658 ike V=root:0:SPOKE:154: sent IKE msg (ident_i1send): 10.40.51.6:500->10.40.19.18:500, len=288, vrf=0, id=1e0221d336ca7dca/0000000000000000 2025-03-27 02:16:19.448501 ike V=root:0: comes 10.40.19.18:500->10.40.51.6:500,ifindex=4,vrf=0,len=188.... 2025-03-27 02:16:19.449795 ike V=root:0: IKEv1 exchange=Identity Protection id=1e0221d336ca7dca/8864bddf3547baa3 len=188 vrf=0 2025-03-27 02:16:19.451185 ike 0: in 2025-03-27 02:16:19.455264 ike V=root:0:SPOKE:154: initiator: main mode get 1st response... 2025-03-27 02:16:19.456336 ike V=root:0:SPOKE:154: VID RFC 3947 4A131C81070358455C5728F20E95452F 2025-03-27 02:16:19.457370 ike V=root:0:SPOKE:154: VID DPD AFCAD71368A1F1C96B8696FC77570100 2025-03-27 02:16:19.458376 ike V=root:0:SPOKE:154: VID FORTIGATE 8299031757A36082C6A621DE00000000 2025-03-27 02:16:19.459453 ike V=root:0:SPOKE:154: peer is FortiGate/FortiOS (v0 b0) 2025-03-27 02:16:19.460419 ike V=root:0:SPOKE:154: VID FRAGMENTATION 4048B7D56EBCE88525E7DE7F00D6C2D3 2025-03-27 02:16:19.461528 ike V=root:0:SPOKE:154: VID FRAGMENTATION 4048B7D56EBCE88525E7DE7F00D6C2D3C0000000 2025-03-27 02:16:19.462745 ike V=root:0:SPOKE:154: selected NAT-T version: RFC 3947 2025-03-27 02:16:19.463694 ike V=root:0:SPOKE:154: negotiation result 2025-03-27 02:16:19.464541 ike V=root:0:SPOKE:154: proposal id = 1: 2025-03-27 02:16:19.465343 ike V=root:0:SPOKE:154:   protocol id = ISAKMP: 2025-03-27 02:16:19.466190 ike V=root:0:SPOKE:154:      trans_id = KEY_IKE. 2025-03-27 02:16:19.467044 ike V=root:0:SPOKE:154:      encapsulation = IKE/none 2025-03-27 02:16:19.467914 ike V=root:0:SPOKE:154:         type=OAKLEY_ENCRYPT_ALG, val=AES_CBC, key-len=128 2025-03-27 02:16:19.469111 ike V=root:0:SPOKE:154:         type=OAKLEY_HASH_ALG, val=SHA2_256. 2025-03-27 02:16:19.470177 ike V=root:0:SPOKE:154:         type=AUTH_METHOD, val=PRESHARED_KEY. 2025-03-27 02:16:19.471202 ike V=root:0:SPOKE:154:         type=OAKLEY_GROUP, val=MODP2048. 2025-03-27 02:16:19.472223 ike V=root:0:SPOKE:154: ISAKMP SA lifetime=600 2025-03-27 02:16:19.473413 ike V=root:0:SPOKE:154: generate DH public value request queued 2025-03-27 02:16:19.474574 ike 0:SPOKE:154: out 2025-03-27 02:16:19.482206 ike V=root:0:SPOKE:154: sent IKE msg (ident_i2send): 10.40.51.6:500->10.40.19.18:500, len=380, vrf=0, id=1e0221d336ca7dca/8864bddf3547baa3 2025-03-27 02:16:19.507744 ike V=root:0: comes 10.40.19.18:500->10.40.51.6:500,ifindex=4,vrf=0,len=380.... 2025-03-27 02:16:19.508968 ike V=root:0: IKEv1 exchange=Identity Protection id=1e0221d336ca7dca/8864bddf3547baa3 len=380 vrf=0 2025-03-27 02:16:19.510335 ike 0: in 2025-03-27 02:16:19.518077 ike V=root:0:SPOKE:154: initiator: main mode get 2nd response... 2025-03-27 02:16:19.519093 ike V=root:0:SPOKE:154: received NAT-D payload type 20 2025-03-27 02:16:19.520047 ike V=root:0:SPOKE:154: received NAT-D payload type 20 2025-03-27 02:16:19.521005 ike V=root:0:SPOKE:154: NAT not detected 2025-03-27 02:16:19.521920 ike V=root:0:SPOKE:154: compute DH shared secret request queued 2025-03-27 02:16:19.524344 ike 0:SPOKE:154: ISAKMP SA 1e0221d336ca7dca/8864bddf3547baa3 key 16:36CA5934AA345F530D5782F6F7E694B7 2025-03-27 02:16:19.525838 ike 0:SPOKE:154: enc 1E0221D336CA7DCA8864BDDF3547BAA305100201000000000000004C0800000C010000000 A2833060000002416FF7CF0976A1D9B42B0D42AB2A6075 F4F592ECA94010A6C3A78B2E70ABF5A56 2025-03-27 02:16:19.527907 ike 0:SPOKE:154: out 2025-03-27 02:16:19.530464 ike V=root:0:SPOKE:154: sent IKE msg (ident_i3send): 10.40.51.6:500->10.40.19.18:500, len=92, vrf=0, id=1e0221d336ca7dca/8864bddf3547baa3 2025-03-27 02:16:19.546604 ike V=root:0: comes 10.40.19.18:500->10.40.51.6:500,ifindex=4,vrf=0,len=92.... 2025-03-27 02:16:19.547864 ike V=root:0: IKEv1 exchange=Identity Protection id=1e0221d336ca7dca/8864bddf3547baa3 len=92 vrf=0 2025-03-27 02:16:19.551539 ike V=root:0:SPOKE:154: initiator: main mode get 3rd response... 2025-03-27 02:16:19.552630 ike 0:SPOKE:154: dec 1E0221D336CA7DCA8864BDDF3547BAA305100201000000000000005C0800000C010000000A 28131200000024500B1F6725297C44D0336560952B1E1 1AC7A7714F9B9DC2A4F42254ABB84962274D3C01EC978FADCEBE048C1E0E8220F 2025-03-27 02:16:19.555218 ike V=root:0:SPOKE:154: peer identifier IPV4_ADDR 10.40.19.18 2025-03-27 02:16:19.556354 ike V=root:0:SPOKE:154: PSK authentication succeeded 2025-03-27 02:16:19.557372 ike V=root:0:SPOKE:154: authentication OK 2025-03-27 02:16:19.558350 ike V=root:0:SPOKE:154: established IKE SA 1e0221d336ca7dca/8864bddf3547baa3 2025-03-27 02:16:19.559779 ike V=root:0:SPOKE:154: check peer route: if_addr4_rcvd=0, if_addr6_rcvd=0, mode_cfg=0 2025-03-27 02:16:19.561097 ike V=root:0:SPOKE: schedule auto-negotiate 2025-03-27 02:16:19.562074 ike V=root:0:SPOKE:154: no pending Quick-Mode negotiations <<<<<<<<<<<< When IPsec SA HARD timeout is reached, phase2 will go down and send 'IPsec SA_DELETE-NOTIFY' to remote VPN peer. FGT1_HO_TLP # 2025-03-27 02:17:54.604806 ike V=root:0:SPOKE: IPsec SA 8763524a/19fb7ed9 hard expired 4 10.40.51.6->10.40.19.18:0 SA count 1 of 1 2025-03-27 02:17:54.606744 ike V=root:0:SPOKE:154: send IPsec SA delete, spi 19fb7ed9 2025-03-27 02:17:54.608167 ike 0:SPOKE:154: enc 1E0221D336CA7DCA8864BDDF3547BAA3081005018688F300000000500C000024D9DA05D8F3947 D1DBE9FFD412323ED50E174417C52C5DBFE64F4627 31869F58E00000010000000010304000119FB7ED9 2025-03-27 02:17:54.610900 ike 0:SPOKE:154: out 1E0221D336CA7DCA8864BDDF3547BAA3081005018688F3000000005C8EAACAE12DCB3E434D2ED2798790E479474B2 EA22874765B621FB4350EAFAC8 E27F64615537F0326511CE2B32BE4C48DD29D37EF046D557F03F0855C2A4729B4 2025-03-27 02:17:54.614717 ike V=root:0:SPOKE:154: sent IKE msg (IPsec SA_DELETE-NOTIFY): 10.40.51.6:500->10.40.19.18:500, len=92, vrf=0, id=1e0221d336ca7dca/8864bddf3 547baa3:8688f300 2025-03-27 02:17:54.618260 ike V=root:0:SPOKE: sending SNMP tunnel DOWN trap for SPOKE 2025-03-27 02:17:54.620117 ike V=root:0:SPOKE: static tunnel down event 0.0.0.0 (dev=24) 2025-03-27 02:17:54.622251 ike V=root:0:SPOKE: static tunnel down event :: (dev=24) With phase2's auto-negotiate enabled, FortiGate will negotiate the IPsec SA keys on reaching soft timeout FGT1_HO_TLP # diagnose vpn ike gateway list vd: root/0 name: SPOKE version: 1 interface: port2 4 addr: 10.40.51.6:500 -> 10.40.19.18:500 tun_id: 10.40.19.18/::10.40.19.18 remote_location: 0.0.0.0 network-id: 0 transport: UDP created: 1007s ago peer-id: 10.40.19.18 peer-id-auth: no pending-queue: 0 IKE SA: created 1/2 established 1/2 time 70/150/230 ms IPsec SA: created 1/4 established 1/4 time 70/182/410 ms id/spi: 157 f1881a09fc68542d/3b91e02697a872e2 direction: initiator status: established 437-437s ago = 70ms proposal: aes128-sha256 key: ac60ab9b0f6e2b9b-de7f71e09b824d14 QKD: no lifetime/rekey: 600/132 DPD sent/recv: 00000000/00000000 peer-id: 10.40.19.18 FGT1_HO_TLP # diagnose vpn tunnel list list all ipsec tunnel in vd 0 ------------------------------------------------------ name=SPOKE ver=1 serial=2 10.40.51.6:0->10.40.19.18:0 nexthop=10.40.51.41 tun_id=10.40.19.18 tun_id6=::10.40.19.18 status=up dst_mtu=1500 weight=1 bound_if=4 real_if=4 lgwy=static/1 tun=intf mode=auto/1 encap=none/552 options[0228]=npu frag-rfc run_state=0 role=primary accept_traffic=1 overlay_id=0 proxyid_num=1 child_num=0 refcnt=4 ilast=2362 olast=2362 ad=/0 stat: rxp=0 txp=0 rxb=0 txb=0 dpd: mode=on-demand on=1 status=ok idle=20000ms retry=3 count=0 seqno=47 natt: mode=none draft=0 interval=0 remote_port=0 fec: egress=0 ingress=0 proxyid=SPOKE proto=0 sa=1 ref=2 serial=5 auto-negotiate src: 0:172.31.196.0-172.31.196.255:0 dst: 0:172.31.131.0-172.31.131.255:0 SA: ref=3 options=38203 type=00 soft=0 mtu=1438 expire=0/0B replaywin=2048 seqno=1 esn=0 replaywin_lastseq=00000000 qat=0 rekey=0 hash_search_len=1 life: type=01 bytes=0/0 timeout=267/300 dec: spi=19fb7edd esp=aes key=16 06299e2c155ef7acc19ac362722756d5 ah=sha256 key=32 630f162ec8db57fb663f8b512a2d273cb782c34be92c3efdad34c6f5896809d1 enc: spi=8763524e esp=aes key=16 4dbaf41aac9031e6b230747d1d29531d ah=sha256 key=32 23f8db79847413f8a5a5d13e05be2bdd81358e1a8503b34798da9e87c0ee3082 dec:pkts/bytes=0/0, enc:pkts/bytes=0/0 npu_flag=00 npu_rgwy=10.40.19.18 npu_lgwy=10.40.51.6 npu_selid=4 dec_npuid=0 enc_npuid=0 FGT1_HO_TLP # 2025-03-27 02:39:46.584774 ike V=root:0:SPOKE:SPOKE: IPsec SA 8763524e/19fb7edd rekey 4 10.40.51.6->10.40.19.18:0 2025-03-27 02:39:46.586306 ike V=root:0:SPOKE:SPOKE: using existing connection 2025-03-27 02:39:46.587305 ike V=root:0:SPOKE:SPOKE: config found 2025-03-27 02:39:46.588346 ike V=root:0:SPOKE:SPOKE: IPsec SA connect 4 10.40.51.6->10.40.19.18:500 negotiating 2025-03-27 02:39:46.589869 ike V=root:0:SPOKE:157:SPOKE:76: generate DH public value request queued 2025-03-27 02:39:46.591377 ike V=root:0:SPOKE:157: cookie f1881a09fc68542d/3b91e02697a872e2:a0a706c8