Skip to main content
RogerDingoDing
RogerDingoDing
Visitor III
January 21, 2025
Question

IPSEC phase 1 SA lifetime not honouring configured setting of 28800

  • January 21, 2025
  • 3 replies
  • 12543 views

hi

 

I am trying to figure out why our fortigate configuration is not honouring the phase 1 lifetime setting of 28800s (8hrs)

Over the weekend I started monitoring the tunnel with pingplotter and noticed a clear pattern as to when the phase 1 rekey happens.

the rekey would start the process after 7hrs 38min, not the 8hrs as configured on the fortigate.

the other thing thats happening is that during this time, network connectivity between the fortigate and azure is down for about 45-60s.

using pingplotter i can see a clear pattern with this and that the rekey happens every 7hrs38min 

(excluding full tunnel drops) causing network connectivity issues along the way.

 

here are the time stamps from pingplotter showing phase1 rekey.
the tunnel drop timestamp indicates that the full tunnel went down.


17/01 - 15:43
17/01 - 23:20 + 7hrs 37min
18/01 - 06:58 + 7hrs 18min (tunnel drop)
18/01 - 14:36 + 7hrs 38min
18/01 - 22:14 + 7hrs 38min
19/01 - 05:52 + 7hrs 38min
19/01 - 13:29 + 7hrs 37min
19/01 - 21:07 + 7hrs 38min
20/01 - 04:45 + 7hrs 38min
20/01 - 12:23 + 7hrs 38min
20/01 - 20:01 + 7hrs 38min (tunnel drop)
21/01 - 03:39 + 7hrs 38min
21/01 - 11:17 + 7hrs 38min

 

as you can see, a distinct pattern is visible.
i have cross checked all these times with app errors, tasks/schedules, fortigate logs etc and they all match up.

 

so my question is...

does anybody know how or why the phase 1 lifetime setting is not working as expected? is this a bug?

7hrs38min is a very random time but its consistent. Also weird that during this time we lose network connectivity.


has anybody seen/come across something like this before?

 

i have raised a ticket with support and waiting for a reply

 

fortigate details

Fortigate 1800F

v7.2.9 build 1688

 

 

cheers,

 

3 replies

pminarik
Staff
pminarik
Staff
January 21, 2025

Strictly speaking, phase1 lifetime is the maximum lifetime of the SA, not a setting for when a rekey itself should happen exactly. Rekey happens before the SA expires in order to ensure there is no disruption due to negotiations not having finished yet.

 

if you run "diag vpn ike gateway list", there is a "lifetime/rekey" line, which will tell you when the rekey will happen (the second value). The initial rekey will always be shorter than the configured lifetime (this is called "soft-timeout"). Once that counter hits zero, FortiGate initiates a rekey.

 

For lifetimes over one hour, the difference from lifetime is 4~5 minutes, for lifetimes under one hour, it should be 20~30 seconds.

 

That is as far as the expectations. Obviously, in your case the rekey seems to happen even sooner, for which I do not have an easy answer. Did you check who is initiating the rekey (ike debug)? Maybe it's the other side, with even more early rekey behaviour?

    RogerDingoDing
    RogerDingoDingAuthor
    Visitor III
    January 21, 2025

    running the command diag vpn ike gateway list shows that the lifetime is set as 28800

    lifetime/rekey: 28800/9904

    interesting you say that for lifetimes over one hour it should be about 4-5 minutes difference.

    in our case its pretty much 22 minutes each time.... and as i mentioned, when this is happening, we experience network connectivity issues between both sites. 

    pingplotter tunnel phase1 rekeys.pngpingplotter tunnel monitoring.png

    as you can see in the images, regular intervals of when we experience the phase 1 rekeys.
    the red triangle indicates a full tunnel drop. 

     

    the other side is an Azure connection, which according to documentation says that the lifetime is hardcoded as 28800 and we can see that 28800 is definitely the setting.
    In regards to who is initiating the rekey... it certainly looks like its the fortigate.

    I have debug ike logs which ive attached, ive removed IPs / Names /Keys etc.

    one thing that really stands out in the debug log is this
    2025-01-20 20:03:55.298017 ike 0:IPSECTUNNEL:38334: 22224544fddffr4rf/3a33434333555ffd negotiation of IKE SA failed due to retry timeout

    which has led me to this kb
    https://community.fortinet.com/t5/FortiGate/Technical-Tip-IKEv2-retransmission-and-DPD/ta-p/294932

     

    heres the debug log.

     

    FORTIGATE # diagnose vpn ike log-filter dst-addr4 10.10.10.10  FORTIGATE # diagnose debug console timestamp enable  FORTIGATE # diagnose debug application ike 63 Debug messages will be on for 21 minutes.  FORTIGATE # diagnose debug enable  FORTIGATE # 2025-01-20 19:59:12.480012 ike shrank heap by 159744 bytes 2025-01-20 20:02:22.289576 ike 0:IPSECTUNNEL: link is idle 0 1.1.1.1->10.10.10.10:0 dpd=1 seqno=286 rr=0 2025-01-20 20:02:22.289619 ike 0:IPSECTUNNEL:38334: send IKEv2 DPD probe, seqno 286 2025-01-20 20:02:22.289659 ike 0:IPSECTUNNEL:295135: sending NOTIFY msg 2025-01-20 20:02:22.289673 ike 0:IPSECTUNNEL:38334:295135: send informational 2025-01-20 20:02:22.289724 ike 0:IPSECTUNNEL:38334: sent IKE msg (INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=12345678989/1234567890:00000010 2025-01-20 20:02:23.169478 ike 0: comes 10.10.10.10:500->1.1.1.1:500,ifindex=35,vrf=0.... 2025-01-20 20:02:23.169509 ike 0: IKEv2 exchange=SA_INIT id=ab12345566777899/0000000000000000 len=388 2025-01-20 20:02:23.169572 ike 0:ab12345566777899/0000000000000000:38444: responder received SA_INIT msg 2025-01-20 20:02:23.169584 ike 0:ab12345566777899/0000000000000000:38444: received notify type NAT_DETECTION_SOURCE_IP 2025-01-20 20:02:23.169600 ike 0:ab12345566777899/0000000000000000:38444: received notify type NAT_DETECTION_DESTINATION_IP 2025-01-20 20:02:23.169609 ike 0:ab12345566777899/0000000000000000:38444: VID MS NT5 ISAKMPOAKLEY KEYVALUE 2025-01-20 20:02:23.169621 ike 0:ab12345566777899/0000000000000000:38444: VID unknown (16): aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa 2025-01-20 20:02:23.169629 ike 0:ab12345566777899/0000000000000000:38444: VID unknown (20): ffffffffffffffffffffffffffffffffffff 2025-01-20 20:02:23.169645 ike 0:ab12345566777899/0000000000000000:38444: incoming proposal: 2025-01-20 20:02:23.169654 ike 0:ab12345566777899/0000000000000000:38444: proposal id = 1: 2025-01-20 20:02:23.169661 ike 0:ab12345566777899/0000000000000000:38444:   protocol = IKEv2: 2025-01-20 20:02:23.169672 ike 0:ab12345566777899/0000000000000000:38444:      encapsulation = IKEv2/none 2025-01-20 20:02:23.169679 ike 0:ab12345566777899/0000000000000000:38444:         type=ENCR, val=AES_CBC (key_len = 256) 2025-01-20 20:02:23.169686 ike 0:ab12345566777899/0000000000000000:38444:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128 2025-01-20 20:02:23.169702 ike 0:ab12345566777899/0000000000000000:38444:         type=PRF, val=PRF_HMAC_SHA2_256 2025-01-20 20:02:23.169709 ike 0:ab12345566777899/0000000000000000:38444:         type=DH_GROUP, val=MODP1024. 2025-01-20 20:02:23.169721 ike 0:ab12345566777899/0000000000000000:38444: matched proposal id 1 2025-01-20 20:02:23.169734 ike 0:ab12345566777899/0000000000000000:38444: proposal id = 1: 2025-01-20 20:02:23.169740 ike 0:ab12345566777899/0000000000000000:38444:   protocol = IKEv2: 2025-01-20 20:02:23.169747 ike 0:ab12345566777899/0000000000000000:38444:      encapsulation = IKEv2/none 2025-01-20 20:02:23.169754 ike 0:ab12345566777899/0000000000000000:38444:         type=ENCR, val=AES_CBC (key_len = 256) 2025-01-20 20:02:23.169764 ike 0:ab12345566777899/0000000000000000:38444:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128 2025-01-20 20:02:23.169771 ike 0:ab12345566777899/0000000000000000:38444:         type=PRF, val=PRF_HMAC_SHA2_256 2025-01-20 20:02:23.169777 ike 0:ab12345566777899/0000000000000000:38444:         type=DH_GROUP, val=MODP1024. 2025-01-20 20:02:23.169784 ike 0:ab12345566777899/0000000000000000:38444: lifetime=28800 2025-01-20 20:02:23.169794 ike 0:ab12345566777899/0000000000000000:38444: SA proposal chosen, matched gateway IPSECTUNNEL 2025-01-20 20:02:23.169805 ike 0: found IPSECTUNNEL 1.1.1.1 0 -> 10.10.10.10:500 2025-01-20 20:02:23.169813 ike 0:IPSECTUNNEL tunnel is on loopback intf, reset oif 35 to 0 2025-01-20 20:02:23.169820 ike 0:IPSECTUNNEL: HA state master(2) 2025-01-20 20:02:23.169829 ike 0:IPSECTUNNEL:38444: processing notify type NAT_DETECTION_SOURCE_IP 2025-01-20 20:02:23.169850 ike 0:IPSECTUNNEL:38444: ignoring unauthenticated notify payload (NAT_DETECTION_SOURCE_IP) 2025-01-20 20:02:23.169858 ike 0:IPSECTUNNEL:38444: processing notify type NAT_DETECTION_DESTINATION_IP 2025-01-20 20:02:23.169871 ike 0:IPSECTUNNEL:38444: ignoring unauthenticated notify payload (NAT_DETECTION_DESTINATION_IP) 2025-01-20 20:02:23.169892 ike 0:IPSECTUNNEL:38444: responder preparing SA_INIT msg 2025-01-20 20:02:23.169913 ike 0:IPSECTUNNEL:38444: generate DH public value request queued 2025-01-20 20:02:23.169928 ike 0:IPSECTUNNEL:38444: responder preparing SA_INIT msg 2025-01-20 20:02:23.169945 ike 0:IPSECTUNNEL:38444: compute DH shared secret request queued 2025-01-20 20:02:23.170042 ike 0:IPSECTUNNEL:38444: responder preparing SA_INIT msg 2025-01-20 20:02:23.170064 ike 0:IPSECTUNNEL:38444: sent IKE msg (SA_INIT_RESPONSE): 1.1.1.1:500->10.10.10.10:500, len=232, vrf=0, id=ab12345566777899/a3444333ss444842 2025-01-20 20:02:23.175480 ike 0: comes 10.10.10.10:500->1.1.1.1:500,ifindex=35,vrf=0.... 2025-01-20 20:02:23.175491 ike 0: IKEv2 exchange=AUTH id=ab12345566777899/a3444333ss444842:00000001 len=224 2025-01-20 20:02:23.175500 ike 0:IPSECTUNNEL: HA state master(2) 2025-01-20 20:02:23.175514 ike 0:IPSECTUNNEL:38444: responder received AUTH msg 2025-01-20 20:02:23.175525 ike 0:IPSECTUNNEL:38444: peer identifier IPV4_ADDR 10.10.10.10 2025-01-20 20:02:23.175541 ike 0:IPSECTUNNEL:38444: auth verify done 2025-01-20 20:02:23.175549 ike 0:IPSECTUNNEL:38444: responder AUTH continuation 2025-01-20 20:02:23.175554 ike 0:IPSECTUNNEL:38444: authentication succeeded 2025-01-20 20:02:23.175568 ike 0:IPSECTUNNEL:38444: responder creating new child 2025-01-20 20:02:23.175585 ike 0:IPSECTUNNEL:38444:295136: peer proposal: 2025-01-20 20:02:23.175594 ike 0:IPSECTUNNEL:38444:295136: TSi_0 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175600 ike 0:IPSECTUNNEL:38444:295136: TSr_0 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175610 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: comparing selectors 2025-01-20 20:02:23.175618 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: matched by rfc-rule-2 2025-01-20 20:02:23.175623 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: phase2 matched by subset 2025-01-20 20:02:23.175634 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: accepted proposal: 2025-01-20 20:02:23.175640 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: TSi_0 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175645 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: TSr_0 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175650 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: autokey 2025-01-20 20:02:23.175666 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: incoming child SA proposal: 2025-01-20 20:02:23.175671 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: proposal id = 1: 2025-01-20 20:02:23.175677 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:   protocol = ESP: 2025-01-20 20:02:23.175681 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:      encapsulation = TUNNEL 2025-01-20 20:02:23.175687 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=ENCR, val=AES_CBC (key_len = 256) 2025-01-20 20:02:23.175697 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=INTEGR, val=SHA256 2025-01-20 20:02:23.175703 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=ESN, val=NO 2025-01-20 20:02:23.175708 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         PFS is disabled 2025-01-20 20:02:23.175713 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: matched proposal id 1 2025-01-20 20:02:23.175718 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: proposal id = 1: 2025-01-20 20:02:23.175723 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:   protocol = ESP: 2025-01-20 20:02:23.175728 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:      encapsulation = TUNNEL 2025-01-20 20:02:23.175739 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=ENCR, val=AES_CBC (key_len = 256) 2025-01-20 20:02:23.175744 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=INTEGR, val=SHA256 2025-01-20 20:02:23.175749 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         type=ESN, val=NO 2025-01-20 20:02:23.175754 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136:         PFS is disabled 2025-01-20 20:02:23.175759 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: lifetime=3600 2025-01-20 20:02:23.175776 ike 0:IPSECTUNNEL:38444: responder preparing AUTH msg 2025-01-20 20:02:23.175784 ike 0:IPSECTUNNEL:38444: established IKE SA ab12345566777899/a3444333ss444842 2025-01-20 20:02:23.175806 ike 0:IPSECTUNNEL:38444: check peer route: if_addr4_rcvd=0, if_addr6_rcvd=0, mode_cfg=0 2025-01-20 20:02:23.175813 ike 0:IPSECTUNNEL: HA send IKE connection add 1.1.1.1->10.10.10.10 2025-01-20 20:02:23.175822 ike 0:IPSECTUNNEL:38444: HA send IKE SA add ab12345566777899/a3444333ss444842 2025-01-20 20:02:23.175830 ike 0:IPSECTUNNEL: schedule auto-negotiate 2025-01-20 20:02:23.175837 ike 0:IPSECTUNNEL:38444: IKE SA is a duplicate of 1234567788990/1234567788990 2025-01-20 20:02:23.175853 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: set sa life soft seconds=3328. 2025-01-20 20:02:23.175861 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: set sa life hard seconds=3600. 2025-01-20 20:02:23.175875 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: IPsec SA selectors #src=1 #dst=1 2025-01-20 20:02:23.175881 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: src 0 7 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175887 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: dst 0 7 0:0.0.0.0-255.255.255.255:0 2025-01-20 20:02:23.175896 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: add IPsec SA: SPIs=1234345/c674edac 2025-01-20 20:02:23.176007 ike 0:IPSECTUNNEL:38444:IPSECTUNNEL:295136: added IPsec SA: SPIs=1234455/c674edac 2025-01-20 20:02:23.176025 ike 0:IPSECTUNNEL: HA send IKE connection add 1.1.1.1->10.10.10.10 2025-01-20 20:02:23.176035 ike 0:IPSECTUNNEL:38444: HA send IKE SA add ab12345566777899/a3444333ss444842 2025-01-20 20:02:23.176046 ike 0:IPSECTUNNEL: HA send IKEv2 message ID update send/recv=0/2 2025-01-20 20:02:23.176072 ike 0:IPSECTUNNEL:38444: sent IKE msg (AUTH_RESPONSE): 1.1.1.1:500->10.10.10.10:500, len=224, vrf=0, id=ab12345566777899/a3444333ss444842:00000001 2025-01-20 20:02:23.179572 ike 0:IPSECTUNNEL: link is idle 0 1.1.1.1->10.10.10.10:0 dpd=1 seqno=287 rr=0 2025-01-20 20:02:23.193072 ike 0:IPSECTUNNEL: HA IPsec send ESP seqno=1aa1e0, num=2 2025-01-20 20:02:25.295294 ike 0:IPSECTUNNEL:38334: sent IKE msg (RETRANSMIT_INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=22224544fddffr4rf/3a33434333555ffd:00000010 2025-01-20 20:02:25.365422 ike 0:IPSECTUNNEL: HA IPsec send ESP seqno=1aa1e0, num=2 2025-01-20 20:02:31.296026 ike 0:IPSECTUNNEL:38334: sent IKE msg (RETRANSMIT_INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=22224544fddffr4rf/3a33434333555ffd:00000010 2025-01-20 20:02:43.297624 ike 0:IPSECTUNNEL:38334: sent IKE msg (RETRANSMIT_INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=22224544fddffr4rf/3a33434333555ffd:00000010 2025-01-20 20:03:07.292576 ike 0:IPSECTUNNEL:38334: sent IKE msg (RETRANSMIT_INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=22224544fddffr4rf/3a33434333555ffd:00000010 2025-01-20 20:03:55.298017 ike 0:IPSECTUNNEL:38334: 22224544fddffr4rf/3a33434333555ffd negotiation of IKE SA failed due to retry timeout 2025-01-20 20:03:55.298056 ike 0:IPSECTUNNEL:38334: expiring IKE SA 22224544fddffr4rf/3a33434333555ffd 2025-01-20 20:03:55.298094 ike 0:IPSECTUNNEL:38334: HA send IKE SA del 22224544fddffr4rf/3a33434333555ffd 2025-01-20 20:03:55.298112 ike 0:IPSECTUNNEL: deleting IPsec SA with SPI 02adeefa 2025-01-20 20:03:55.298167 ike 0:IPSECTUNNEL:IPSECTUNNEL: deleted IPsec SA with SPI 02adeefa, SA count: 1 2025-01-20 20:03:55.298200 ike 0:IPSECTUNNEL:38334:295140: send informational 2025-01-20 20:03:55.298259 ike 0:IPSECTUNNEL:38334: sent IKE msg (INFORMATIONAL): 1.1.1.1:500->10.10.10.10:500, len=80, vrf=0, id=22224544fddffr4rf/3a33434333555ffd:00000010 2025-01-20 20:03:55.298281 ike 0:IPSECTUNNEL: schedule auto-negotiate 2025-01-20 20:05:53.298711 ike shrank heap by 159744 bytes 2025-01-20 20:06:13.332328 ike shrank heap by 159744 bytes 2025-01-20 20:07:25.363311 ike 0:IPSECTUNNEL: HA IPsec send ESP seqno=95803, num=1

     


     

    pminarik
    Staff
    pminarik
    Staff
    January 22, 2025

    ike 0: comes 10.10.10.10:500->1.1.1.1:500,ifindex=35,vrf=0....
    ike 0: IKEv2 exchange=SA_INIT id=ab12345566777899/0000000000000000 len=388
    ike 0:ab12345566777899/0000000000000000:38444: responder received SA_INIT msg

     

    This is an incoming packet, of type SA_INIT, therefore the other side is the initiator, and the FortiGate is the responder (as it correctly notes in the third line).

    A proper rekey is negotiated via CREATE_CHILD_SA. On the other hand, SA_INIT is for a brand new SA. A rekey results in existing phase2 SAs being inherited by the new p1 SA, a fresh SA_INIT does not (all p2s are dropped and need to be renegotiated, high potential for temporary traffic loss). Assuming there was an existing phase1 SA at this point, this in essence means that the other side has abruptly destroyed the existing p1+p2 and is negotiating everything fresh. Why? Not possible to say from this debug. You can try checking what happened earlier before this, but it's not guaranteed that FortiGate's own debugs will have the answer. Maybe it's just some aberration on the other side that we can't see.

     

    ike 0:IPSECTUNNEL:38444: IKE SA is a duplicate of 1234567788990/1234567788990

    ...

    ike 0:IPSECTUNNEL:38334: expiring IKE SA 22224544fddffr4rf/3a33434333555ffd

    ...

    ike 0:IPSECTUNNEL: deleting IPsec SA with SPI 02adeefa

    ike 0:IPSECTUNNEL:IPSECTUNNEL: deleted IPsec SA with SPI 02adeefa, SA count: 1

     

    Lastly, these are just the consequences of the above not being a rekey but a fresh new SA_INIT: all existing phase1/2 SAs get scrapped.

      RogerDingoDing
      RogerDingoDingAuthor
      Visitor III
      February 5, 2025

      hi,

      I managed to grab a wireshark capture from the diagnostics option in the GUI. The capture was targeting the Azure IP, however there was nothing there to indicate any network issues between the 2 locations. No drops or anything to indicate a timeout issue.

       

      most of the capture contains this ESP protocol info.

       

       

      1 0.000000 FORTIGATEIP AZUREIP ESP 138 ESP (SPI=0x4fac85ac) 2 0.084981 FORTIGATEIP AZUREIP ESP 826 ESP (SPI=0x4fac85ac) 3 0.084989 FORTIGATEIP AZUREIP ESP 730 ESP (SPI=0x4fac85ac) 4 0.084993 FORTIGATEIP AZUREIP ESP 810 ESP (SPI=0x4fac85ac) 5 0.084997 FORTIGATEIP AZUREIP ESP 858 ESP (SPI=0x4fac85ac) 6 0.085001 FORTIGATEIP AZUREIP ESP 826 ESP (SPI=0x4fac85ac)

       


      theres an occasional warning in the ESP packets that mentions the following. 

       

      Encapsulating Security Payload  ESP SPI: 0x4fac85ac (1336706476)  ESP Sequence: 1725441  [Expected SN: 1724730 (711 SNs missing)]  [Expert Info (Warning/Sequence): Wrong Sequence Number for SPI 4fac85ac - 711 missing]  [Wrong Sequence Number for SPI 4fac85ac - 711 missing]  [Severity level: Warning]  [Group: Sequence]  [Previous Frame: 5921]

       

       

      the only other info in the capture that is different to the above is this

       

       

      5787	74.918812	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 5874	75.918826	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 5922	76.926868	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 6159	79.938075	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 6597	86.945831	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 7599	100.956426	AZUREIP	FORTIGATEIP	ISAKMP	362	CREATE_CHILD_SA MID=02 Initiator Request 14239	181.661070	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request 14460	182.855993	AZUREIP	FORTIGATEIP	ISAKMP	430	IKE_SA_INIT MID=00 Initiator Request 14461	182.856582	FORTIGATEIP	AZUREIP	ISAKMP	274	IKE_SA_INIT MID=00 Responder Response 14462	182.861951	AZUREIP	FORTIGATEIP	ISAKMP	266	IKE_AUTH MID=01 Initiator Request 14463	182.862558	FORTIGATEIP	AZUREIP	ISAKMP	266	IKE_AUTH MID=01 Responder Response 14622	184.663714	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request 15197	190.668750	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request 16234	202.668321	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request 17870	226.670918	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request 21839	274.669037	FORTIGATEIP	AZUREIP	ISAKMP	122	INFORMATIONAL MID=16 Responder Request

       

       

      as i said, no mention of any IKE SA timeout errors in the packet capture. Is there a way to configure the packet capture to grab more indepth info? 


      Following advise from fortinet support we made the following changes our IPsec tunnel.

       

      • enable PFS for phase 2, group 19
      • enable PFS in azure, set as ECP256
      • change DPD settings, set as retry count 6, interval 15s

       

      these change seem to have made a difference in terms of the length of the network drop.. it is now down for 30s instead of 60s during the rekey phase.

       

      the error negotiation of IKE SA failed due to retry timeout is still happening.

       

      heres the latest debug log from today.

       

       

      Fortigate # 2025-02-05 10:52:59.099430 ike shrank heap by 159744 bytes 2025-02-05 10:54:46.988125 ike 0:IPSECTUNNEL: HA IPsec send ESP seqno=f30000, num=1 2025-02-05 10:56:48.225776 ike 0:IPSECTUNNEL: link is idle 0 FORTIGATEIP->AZUREIP:0 dpd=2 seqno=7 rr=0 2025-02-05 10:56:48.225817 ike 0:IPSECTUNNEL:4119: send IKEv2 DPD probe, seqno 7 2025-02-05 10:56:48.225859 ike 0:IPSECTUNNEL:15626: sending NOTIFY msg 2025-02-05 10:56:48.225871 ike 0:IPSECTUNNEL:4119:15626: send informational 2025-02-05 10:56:48.225889 ike 0:IPSECTUNNEL:4119: enc 0F0E0D0C0Bdfdfdf0A0908070605040302010F 2025-02-05 10:56:48.225931 ike 0:IPSECTUNNEL:4119: out F57DAFA69F19718B6D41A0080dfdfd343434fjkj9F44BD62E2025000000001000000050000000344BA3D960FD81258F6DF45CD53C5BDD2CF7F3FA3D360 6FB30B26CADAFF6F1C62602429A68789EF7E933FAFFD6C4F989FE 2025-02-05 10:56:48.225958 ike 0:IPSECTUNNEL:4119: sent IKE msg (INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa69f19718b/6d41a008 09f44bd6:00000010 2025-02-05 10:56:49.335175 ike 0: comes AZUREIP:500->FORTIGATEIP:500,ifindex=35,vrf=0.... 2025-02-05 10:56:49.335214 ike 0: IKEv2 exchange=SA_INIT id=5a54cf6ff8006108/0000000000000000 len=388 2025-02-05 10:56:49.335252 ike 0: in 5A54CF6FF80061080000000000000000212022080000000000000184220000300000002C010100040300000C0100000C800E0100030000080300000C030000080 200000500000008040000022800008800020000959D5CC7C546889A79D168B0A84BDC3CC4664DGESG0F347ACBE9AFCCEBEBF46A60A28678227E6B95A26EBDCBFA3264A97E9D7E20A543433BE346BBFAC77BB5C848A82 38D41E4A44A2D62BC69C612301F5F7172E9AE29E3293610BD9E8C7A4118872DEB8F89DD33886C34209B17CCF1B432181FE2975558D7537E79A5873D37DF888660046C29000034E580EF2148CAC1F49263D5893F875 CC405967B4B6A24C01CE4073F9A215332F358DC9D53A4BD0DC45F8E7952E218E218290000DDGH1C00004004317BE95A8185508B28F07D9BE6E33912AD6C010A2B00001C00004005BCFCF63B0FB087CF6AE067D96CB C443EAD1CBE3E2B0000181E2B51690599D333HJ1C7D7C96FCBFB587E461000000092B000014FB1DE3CDF341B7EA16B7E5BE0855F1200000001801528BBBC00696121849AB9A1C5B2A5100000002 2025-02-05 10:56:49.335280 ike 0:5a54cf6ff8006108/0000000000000000:5115: responder received SA_INIT msg 2025-02-05 10:56:49.335295 ike 0:5a54cf6ff8006108/0000000000000000:5115: received notify type NAT_DETECTION_SOURCE_IP 2025-02-05 10:56:49.335305 ike 0:5a54cf6ff8006108/0000000000000000:5115: received notify type NAT_DETECTION_DESTINATION_IP 2025-02-05 10:56:49.335314 ike 0:5a54cf6ff8006108/0000000000000000:5115: VID MS NT5 ISAKMPOAKLEY 1E2B51690HKLYRXBJ15991C7D7C96FCBFB587E46100000009 2025-02-05 10:56:49.335323 ike 0:5a54cf6ff8006108/0000000000000000:5115: VID unknown (16): FB1DE3CDF3FHJ4DDA41B7EA16B7E5BE0855F120 2025-02-05 10:56:49.335332 ike 0:5a54cf6ff8006108/0000000000000000:5115: VID unknown (20): 01528BBBC4560069612UKYD11331849AB9A1C5B2A5100000002 2025-02-05 10:56:49.335343 ike 0:5a54cf6ff8006108/0000000000000000:5115: incoming proposal: 2025-02-05 10:56:49.335357 ike 0:5a54cf6ff8006108/0000000000000000:5115: proposal id = 1: 2025-02-05 10:56:49.335364 ike 0:5a54cf6ff8006108/0000000000000000:5115:   protocol = IKEv2: 2025-02-05 10:56:49.335370 ike 0:5a54cf6ff8006108/0000000000000000:5115:      encapsulation = IKEv2/none 2025-02-05 10:56:49.335377 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=ENCR, val=AES_CBC (key_len = 256) 2025-02-05 10:56:49.335385 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128 2025-02-05 10:56:49.335391 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=PRF, val=PRF_HMAC_SHA2_256 2025-02-05 10:56:49.335399 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=DH_GROUP, val=MODP1024. 2025-02-05 10:56:49.335413 ike 0:5a54cf6ff8006108/0000000000000000:5115: matched proposal id 1 2025-02-05 10:56:49.335423 ike 0:5a54cf6ff8006108/0000000000000000:5115: proposal id = 1: 2025-02-05 10:56:49.335430 ike 0:5a54cf6ff8006108/0000000000000000:5115:   protocol = IKEv2: 2025-02-05 10:56:49.335437 ike 0:5a54cf6ff8006108/0000000000000000:5115:      encapsulation = IKEv2/none 2025-02-05 10:56:49.335443 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=ENCR, val=AES_CBC (key_len = 256) 2025-02-05 10:56:49.335450 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128 2025-02-05 10:56:49.335457 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=PRF, val=PRF_HMAC_SHA2_256 2025-02-05 10:56:49.335464 ike 0:5a54cf6ff8006108/0000000000000000:5115:         type=DH_GROUP, val=MODP1024. 2025-02-05 10:56:49.335470 ike 0:5a54cf6ff8006108/0000000000000000:5115: lifetime=28800 2025-02-05 10:56:49.335479 ike 0:5a54cf6ff8006108/0000000000000000:5115: SA proposal chosen, matched gateway IPSECTUNNEL 2025-02-05 10:56:49.335495 ike 0: found IPSECTUNNEL FORTIGATEIP 0 -> AZUREIP:500 2025-02-05 10:56:49.335502 ike 0:IPSECTUNNEL tunnel is on loopback intf, reset oif 35 to 0 2025-02-05 10:56:49.335510 ike 0:IPSECTUNNEL: HA state master(2) 2025-02-05 10:56:49.335521 ike 0:IPSECTUNNEL:5115: processing notify type NAT_DETECTION_SOURCE_IP 2025-02-05 10:56:49.335545 ike 0:IPSECTUNNEL:5115: ignoring unauthenticated notify payload (NAT_DETECTION_SOURCE_IP) 2025-02-05 10:56:49.335557 ike 0:IPSECTUNNEL:5115: processing notify type NAT_DETECTION_DESTINATION_IP 2025-02-05 10:56:49.335567 ike 0:IPSECTUNNEL:5115: ignoring unauthenticated notify payload (NAT_DETECTION_DESTINATION_IP) 2025-02-05 10:56:49.335588 ike 0:IPSECTUNNEL:5115: responder preparing SA_INIT msg 2025-02-05 10:56:49.335606 ike 0:IPSECTUNNEL:5115: generate DH public value request queued 2025-02-05 10:56:49.335619 ike 0:IPSECTUNNEL:5115: responder preparing SA_INIT msg 2025-02-05 10:56:49.335631 ike 0:IPSECTUNNEL:5115: compute DH shared secret request queued 2025-02-05 10:56:49.335724 ike 0:IPSECTUNNEL:5115: responder preparing SA_INIT msg 2025-02-05 10:56:49.335735 ike 0:IPSECTUNNEL:5115: out 5A54CF6FF8006108EE598C4E534566F4F1A92120222000000000000000E8220000300000002C010100040300000C0100000C800E0100030 0000802000005030000080300000C000000080400000228000088000200002922AB1A5196BC4C7CA5798DAE13JLLEE1A50B598AB45AC8EE9C2800F98C0989930C7E03BAEFA3498C54C3E4FA4B5324DB5F3295FAB064 B44574B5F6B63706E4338B7273BD95FCA222AC4569E4A9EFDC5DF877C2F97EE3EA930BBF5DDCCE35B3027EC0432392238B612DEF0580790F52DD7578D77F2ECB69E7C014DA918C9B56973C900000014BBAD6D4 11587B2CBA42D33A5CCB20663 2025-02-05 10:56:49.335768 ike 0:IPSECTUNNEL:5115: sent IKE msg (SA_INIT_RESPONSE): FORTIGATEIP:500->AZUREIP:500, len=232, vrf=0, id=5a54cf6ff8006108/ee59 8c4e56f4f1a9 2025-02-05 10:56:49.335816 ike 0:IPSECTUNNEL:5115: IKE SA 5a54cf6f466f8006108/ee598c4e56f4f1a9 SK_ei 32:29D732527316644546EE82D7AEB799C9D000ECCA33E497F5489C41CF8A364BA158A2 083 2025-02-05 10:56:49.335826 ike 0:IPSECTUNNEL:5115: IKE SA 5a5455cf6ff8006108/ee598c4e56f664f1a9 SK_er 32:1ED8CD2646343FC9A95A12008634280AF299685E3163FAB9255ADBE24EB8BBD6B 47C 2025-02-05 10:56:49.335833 ike 0:IPSECTUNNEL:5115: IKE SA 5a54cf6ff668006108/ee598c4e5666f4f1a9 SK_ai 32:CEAD9740BF6256C0993A07A5B0F292F937B52B29E3867403F92695C69A17D EB4 2025-02-05 10:56:49.335839 ike 0:IPSECTUNNEL:5115: IKE SA 5a54cf666ff8006108/ee598c4e5666f4f1a9 SK_ar 32:63E7C9D81114E2AFWYW9A8B043A3A9F233F9AB4943A4AAD50999C0F15E59DC5F D44 2025-02-05 10:56:49.341056 ike 0: comes AZUREIP:500->FORTIGATEIP:500,ifindex=35,vrf=0.... 2025-02-05 10:56:49.341070 ike 0: IKEv2 exchange=AUTH id=5a54cf6ff803406108/ee598c4e53436f4f1a9:00000001 len=224 2025-02-05 10:56:49.341082 ike 0: in 5A54CF6FF8006108EE598sC4E56F4F1A92E20230800000001000000E0230000C46BEDEE47749A562237688FDC7409F4D26A912951E0FB3B20561F916A339FD22E3 4F4F608A4320826A808702D3BC755BC2A92728C32B16D5956C558CF4EE940ss401903FCB438C39A1D13C836EF7D82303B1586B52333s1E47ED3A709462D0266E0C3077D29100F26489BDA6C3F4CCCA919AB3439C08E58 7F916621C0DA44033B12B9124E41FF0BA06D34FF217E4034C45E638126D7E88D20B03FD29E3FB8816657917727E80394D03A7CE7E5514F9C4D25A2080DEBCDD131103CF07EA2983266045404755 2025-02-05 10:56:49.341091 ike 0:IPSECTUNNEL: HA state master(2) 2025-02-05 10:56:49.341115 ike 0:IPSECTUNNEL:5115: dec 5A54CF6FF8006108EE598C4E56F466F1A92E20230800000001000000B023000004270066000C01000000145AD8A0210000280200000096C 48BFBE5C7FA54E2FB9A6AE9F390EB24B429972819EC38D3FD9994022EE4FE22C00002C00000028010304038A65CA880300000C0100000C874300E0100030000080300000C00000008050000002D000018010000000 70000100000FFFF00000000FFFFFFFF0220000018010000000700001000200FFFF000000200FFFFFFFF 2025-02-05 10:56:49.341125 ike 0:IPSECTUNNEL:5115: responder received AUTH msg 2025-02-05 10:56:49.341141 ike 0:IPSECTUNNEL:5115: peer identifier IPV4_ADDR AZUREIP 2025-02-05 10:56:49.341161 ike 0:IPSECTUNNEL:5115: auth verify done 2025-02-05 10:56:49.341172 ike 0:IPSECTUNNEL:5115: responder AUTH continuation 2025-02-05 10:56:49.341178 ike 0:IPSECTUNNEL:5115: authentication succeeded 2025-02-05 10:56:49.341195 ike 0:IPSECTUNNEL:5115: responder creating new child 2025-02-05 10:56:49.341210 ike 0:IPSECTUNNEL:5115:15627: peer proposal: 2025-02-05 10:56:49.341216 ike 0:IPSECTUNNEL:5115:15627: TSi_0 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341222 ike 0:IPSECTUNNEL:5115:15627: TSr_0 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341233 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: comparing selectors 2025-02-05 10:56:49.341239 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: matched by rfc-rule-2 2025-02-05 10:56:49.341245 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: phase2 matched by subset 2025-02-05 10:56:49.341251 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: accepted proposal: 2025-02-05 10:56:49.341256 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: TSi_0 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341262 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: TSr_0 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341267 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: autokey 2025-02-05 10:56:49.341276 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: incoming child SA proposal: 2025-02-05 10:56:49.341285 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: proposal id = 1: 2025-02-05 10:56:49.341289 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:   protocol = ESP: 2025-02-05 10:56:49.341294 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:      encapsulation = TUNNEL 2025-02-05 10:56:49.341299 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=ENCR, val=AES_CBC (key_len = 256) 2025-02-05 10:56:49.341305 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=INTEGR, val=SHA256 2025-02-05 10:56:49.341310 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=ESN, val=NO 2025-02-05 10:56:49.341315 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         PFS is disabled 2025-02-05 10:56:49.341321 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: matched proposal id 1 2025-02-05 10:56:49.341325 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: proposal id = 1: 2025-02-05 10:56:49.341330 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:   protocol = ESP: 2025-02-05 10:56:49.341335 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:      encapsulation = TUNNEL 2025-02-05 10:56:49.341340 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=ENCR, val=AES_CBC (key_len = 256) 2025-02-05 10:56:49.341345 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=INTEGR, val=SHA256 2025-02-05 10:56:49.341350 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         type=ESN, val=NO 2025-02-05 10:56:49.341361 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627:         PFS is disabled 2025-02-05 10:56:49.341367 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: lifetime=3600 2025-02-05 10:56:49.341384 ike 0:IPSECTUNNEL:5115: responder preparing AUTH msg 2025-02-05 10:56:49.341392 ike 0:IPSECTUNNEL:5115: established IKE SA 5a54cf336ff8006108/ee598544e56f4f1a9 2025-02-05 10:56:49.341408 ike 0:IPSECTUNNEL:5115: check peer route: if_addr4_rcvd=0, if_addr6_rcvd=0, mode_cfg=0 2025-02-05 10:56:49.341415 ike 0:IPSECTUNNEL: HA send IKE connection add FORTIGATEIP->AZUREIP 2025-02-05 10:56:49.341425 ike 0:IPSECTUNNEL:5115: HA send IKE SA add 5a54cf346ff8006108/ee598c4545e56f4f1a9 2025-02-05 10:56:49.341433 ike 0:IPSECTUNNEL: schedule auto-negotiate 2025-02-05 10:56:49.341449 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: set sa life soft seconds=3331. 2025-02-05 10:56:49.341454 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: set sa life hard seconds=3600. 2025-02-05 10:56:49.341468 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: IPsec SA selectors #src=1 #dst=1 2025-02-05 10:56:49.341475 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: src 0 7 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341486 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: dst 0 7 0:0.0.0.0-255.255.255.255:0 2025-02-05 10:56:49.341491 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: add IPsec SA: SPIs=ddfeadfe/8a65ca88 2025-02-05 10:56:49.341496 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: IPsec SA dec spi ddfeadfe key 32:374DABB354B76A865545C6A3B169331D7E82C005C8A10B6DE3EFAC2E14E5 80408AB3 auth 32:9E3988B87A163BC78CE04A9A0B128246533161ECD5848BC1CC1254D3E08482C5 2025-02-05 10:56:49.341502 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: IPsec SA enc spi 8a65ca88 key 32:60A4037D8540B36952E07FE57454594C79B1F8E1461A9E4631495446A5C1 38FA0340 auth 32:C0D87C38BB6853104E9F4473395AD762C683309C44FC4375B703733F69C6B829 2025-02-05 10:56:49.341577 ike 0:IPSECTUNNEL:5115:IPSECTUNNEL:15627: added IPsec SA: SPIs=ddfeadfe/8a65ca88 2025-02-05 10:56:49.341597 ike 0:IPSECTUNNEL: HA send IKE connection add FORTIGATEIP->AZUREIP 2025-02-05 10:56:49.341605 ike 0:IPSECTUNNEL:5115: HA send IKE SA add 5a54cf6ff8006108/ee598c4e56f4f1a9 2025-02-05 10:56:49.341611 ike 0:IPSECTUNNEL: HA send IKEv2 message ID update send/recv=0/2 2025-02-05 10:56:49.341620 ike 0:IPSECTUNNEL:5115: enc 2700000C0100000040FD20C42100045750280200000065807240C0A516CE96B0A6F17B2D84A9733F92881DD5F55CEA6A224E4897A25F2C0 0002C0000002801030403DDFEADFE0300000C0100000C800E01000300000803045430000C00000008050000002D0220001801000000070000100000FFFF00000000FFFFFFFF0000001801000000070000100000FFFF0 0000000FFFFFFFF0F0E0D0C0B0A0908070605040302010F 2025-02-05 10:56:49.341647 ike 0:IPSECTUNNEL:5115: out 5A54CF6FF8006108EE598C4E56F4F1A92E20232000000001000000E0240000C4DAEE19CBA9E9E99E5AA5512563F8B836D88947E67A7 C5ABC53DE07B68F1AC34DA60E39609A3F9457F981DE5ADFB431834C2C1738ACADDAE6A207DA8AEC72CD72CA33E314823B1E84E1C63BD78ADB8D419428DFBAFF3AA5CFDF2AE88EFC536B6EF573E4C286A044FBC4FCE 68D4DCF6EC92187C9CE4EC11C443AA01960BA130256A4EAD2EA128D560710FAA0CED6DC62782776C7B1D97CC292A7677C0398722ACFAB19233F41A3EE2D26C2748542D889F02E61E66345E01407AFED916C80BEF3C2C5B F889DB141 2025-02-05 10:56:49.341672 ike 0:IPSECTUNNEL:5115: sent IKE msg (AUTH_RESPONSE): FORTIGATEIP:500->AZUREIP:500, len=224, vrf=0, id=5a54cf6ff8332006108/ee598c4 e56f4f1a9:00000001 2025-02-05 10:56:49.344490 ike 0:IPSECTUNNEL: HA IPsec send ESP seqno=1138a4c, num=2 2025-02-05 10:56:49.345761 ike 0:IPSECTUNNEL: link is idle 0 FORTIGATEIP->AZUREIP:0 dpd=2 seqno=8 rr=0 2025-02-05 10:56:51.234380 ike 0:IPSECTUNNEL:4119: out F57DAFA69F133367899718B6D41A00809F44BD62E2025000000001000000050000000344BA3D960FD81258F6DF45C45453C5BDD2CF7F3FA3D360 6FB30B26CADAFF6F1C62602429A68789EF7E933FAFFD6C4F989FE 2025-02-05 10:56:51.234420 ike 0:IPSECTUNNEL:4119: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa4469f1971 8b/6d41a00809f44bd6:00000010 2025-02-05 10:56:57.230978 ike 0:IPSECTUNNEL:4119: out F57DAFA69F19718B6D41A008045799F44BD62E2025000000001000000050000000344BA3D960FD81258F6DF45CD53C5BDD2CF7F3FA3D360 6FB30B26CADAFF6F1C62602429A68789EF7E933FAFFD6C4F989FE 2025-02-05 10:56:57.231019 ike 0:IPSECTUNNEL:4119: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa6954f1971 8b/6d41a00809f44bd6:00000010 2025-02-05 10:57:09.227271 ike 0:IPSECTUNNEL:4119: out F57DAFA69F19718B6D41A00809F44BD62E2025000000001000000050000000344BA3D960FD81258F6DF45CD53C5BDD2CF7F3FA3D360 6FB30B26CADAFF6F1C62602429A68789EF7E933FAFFD6C4F989FE 2025-02-05 10:57:09.227326 ike 0:IPSECTUNNEL:4119: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa4469f1971 8b/6d41a00809f44bd6:00000010 2025-02-05 10:57:33.233982 ike 0:IPSECTUNNEL:4119: out F57DAFA69F19718B6D41A00342809F44BD62E20250000000015000000050000000344BA3D960FD81258F6DF45CD53C5BDD2CF7F3FA3D360 6FB30B26CADAFF6F1C62602429A68783349EF7E933FAFFD6C4F989FE 2025-02-05 10:57:33.234040 ike 0:IPSECTUNNEL:4119: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa5569f1971 8b/6d41a00809f44bd6:00000010 2025-02-05 10:58:21.234603 ike 0:IPSECTUNNEL:4119: f57dafdf69f19718b/6d41a0080df9f44bd6 negotiation of IKE SA failed due to retry timeout 2025-02-05 10:58:21.234645 ike 0:IPSECTUNNEL:4119: expiring IKE SA f57dafaa69f19718b/6d41a0a0809f44bd6 2025-02-05 10:58:21.234681 ike 0:IPSECTUNNEL:4119: HA send IKE SA del f57dafa69fa19718b/6d41a0080a9f44bd6 2025-02-05 10:58:21.234701 ike 0:IPSECTUNNEL: deleting IPsec SA with SPI f9aab906 2025-02-05 10:58:21.234759 ike 0:IPSECTUNNEL:IPSECTUNNEL: deleted IPsec SA with SPI f9aab906, SA count: 1 2025-02-05 10:58:21.234794 ike 0:IPSECTUNNEL:4119:15634: send informational 2025-02-05 10:58:21.234811 ike 0:IPSECTUNNEL:4119: enc 0000000801d3340000000706050403020107 2025-02-05 10:58:21.234854 ike 0:IPSECTUNNEL:4119: out F57DAFA69F19718B6D41A008DF3409F44BD62E20250000000010000000502A00003471D9AC75651C147B55A434GFDA8355A771621429F51495E8 DCC734E4598334451EB57260F7FE2E052567C01CD9DACB2A0E0FEAF5 2025-02-05 10:58:21.234881 ike 0:IPSECTUNNEL:4119: sent IKE msg (INFORMATIONAL): FORTIGATEIP:500->AZUREIP:500, len=80, vrf=0, id=f57dafa6349f19718b/6d4134a008 09f44bd6:00000010 2025-02-05 10:58:21.234902 ike 0:IPSECTUNNEL: schedule auto-negotiate 2025-02-05 10:58:39.782591 ike shrank heap by 159744 bytes

       


      anything stand out to you or is it the same as before?

       

       

      cheers,

      RogerDingoDing
      RogerDingoDingAuthor
      Visitor III
      February 12, 2025

      we found the root cause of our issues.


      the IPsec tunnel was configured with a 'loopback interface', and for whatever reason this was causing the timeout errors and network drops. (further investigation into this will be happening)

       

      Once I discovered that we were having a large amount of malformed packets during the ike rekey phase it got us wondering what could be causing this... something on the network most likely.
      So at a whim and advice from a 3rd party who suggested we change interface for the tunnel to the WAN port.

      We made the change today and can confirm that during the latest rekey phase there was no network drop, the debug logs are clean (no IKE SA timeout errors) and the wireshark captures also look much cleaner. 

       

      now that the loopback was identified, i had something else to investigate.
      came across this article where the background describes the behaviour we were experiencing.

      Site-to-Site IPsec VPN cannot establish i... - Fortinet Community

       

      Background:

      FortiOS IKE (IPsec phase1) and ESP (IPsec phase2) are separate sessions when nat-traversal is not enforced, therefore when IPsec VPN is bound to a loopback interface and there are redundant ISPs (ECMP), then by design IKE and ESP traffic could be asymmetric and follow different paths where inbound and outbound IKE traffic could be routed over different interfaces, on some implementations this asymmetric behavior could cause VPN tunnel fails to establish.

       

      also found this 
      Best practice when IPSec VPN is bound to ... - Fortinet Community

       

      So based on both these articles and the settings that they mention, its highly possible that we had missing configuration for an ipsec tunnel with a loopback interface.
      we have also reached out to the ISP to confirm that everything is correct on their end as well.

      further investigation will continue into this as we will want to have the loopback interface working correctly.

       

      time to celebrate!

       

      Terms & ConditionsAccessibility statement