Support Forum
The Forums are a place to find answers on a range of Fortinet products from peers and product experts.
RogerDingoDing
New Contributor

IPSEC phase 1 SA lifetime not honouring configured setting of 28800

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,

 

14 REPLIES 14
pminarik
Staff
Staff

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?

[ corrections always welcome ]
RogerDingoDing

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

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.

[ corrections always welcome ]
RogerDingoDing

hey

 

thanks for the detailed feedback, thats really helpful.. lots to go over here.
i have the corresponding Azure logs for the same time stamps... 

 

looking at the 2d line here, it says [SEND][CHILD_SA MM_REKEY] Sending IKE rekey packet. 
This matches up with what you are saying, that the azure connection is the initiator making the fortigate the responder.
the azure connection mode is set as Default, i wonder if we should change this to responder only.

 

Screenshot 2025-01-22 111242.png



So are you saying that the rekey SA is not being negotiated correctly because you cannot see the CREATE_CHILD_SA entry?

and because this isnt being created, when the existing SA key expires, it doesnt do it seamlessly...therefore causing the network drop as it recreates the SA keys?

 

 

8pm logs

1/20/2025, 8:00:35.444 PM   
1/20/2025, 8:00:35.444 PMFortigateIPAzureIP[SEND][CHILD_SA MM_REKEY] Sending IKE rekey packet with tunnelId 0x26, iCookie 0x91FF429C563123FD and rCookie 0x0
1/20/2025, 8:00:35.446 PMFortigateIPAzureIP[SEND]Sending Ike payload for tunnel Id 0x26: Policy1:Cipher=AES-CBC-256 Integrity=SHA256 DhGroup=DhGroup2 
1/20/2025, 8:00:36.460 PMFortigateIPAzureIP[SEND]Sending IKE retransmit packet with tunnelId 0x26, iCookie 0x218502108C31DB79 and rCookie 0x3A47FFDBC200DD31  Packet Info Exchange type: IKEv2 Create Child Mode Length 320 NextPayload ENCR Flags 0x8 Messid 0x00000002
1/20/2025, 8:00:37.470 PMFortigateIPAzureIP[SEND]Sending IKE retransmit packet with tunnelId 0x26, iCookie 0x218502108C31DB79 and rCookie 0x3A47FFDBC200DD31  Packet Info Exchange type: IKEv2 Create Child Mode Length 320 NextPayload ENCR Flags 0x8 Messid 0x00000002
1/20/2025, 8:00:40.477 PMFortigateIPAzureIP[SEND]Sending IKE retransmit packet with tunnelId 0x26, iCookie 0x218502108C31DB79 and rCookie 0x3A47FFDBC200DD31  Packet Info Exchange type: IKEv2 Create Child Mode Length 320 NextPayload ENCR Flags 0x8 Messid 0x00000002
1/20/2025, 8:00:47.484 PMFortigateIPAzureIP[SEND]Sending IKE retransmit packet with tunnelId 0x26, iCookie 0x218502108C31DB79 and rCookie 0x3A47FFDBC200DD31  Packet Info Exchange type: IKEv2 Create Child Mode Length 320 NextPayload ENCR Flags 0x8 Messid 0x00000002
1/20/2025, 8:01:01.494 PMFortigateIPAzureIP[SEND]Sending IKE retransmit packet with tunnelId 0x26, iCookie 0x218502108C31DB79 and rCookie 0x3A47FFDBC200DD31  Packet Info Exchange type: IKEv2 Create Child Mode Length 320 NextPayload ENCR Flags 0x8 Messid 0x00000002
1/20/2025, 8:01:15.507 PM   
1/20/2025, 8:01:15.507 PM   
1/20/2025, 8:01:15.507 PM   
1/20/2025, 8:02:22.069 PMFortigateIPAzureIP[LOCAL_MSG] IKE Tunnel closed for tunnelId 0x26 with status Main mode SA lifetime expired or peer sent a main mode delete.
1/20/2025, 8:02:22.129 PM   
1/20/2025, 8:02:22.129 PM   
1/20/2025, 8:02:22.129 PMFortigateIPAzureIP[LOCAL_MSG] IKE Tunnel closed for tunnelId 0x26 with status {Object Exists}

An attempt was made to create an object and the object name already existed.
1/20/2025, 8:02:22.280 PM   
1/20/2025, 8:02:23.153 PMFortigateIPAzureIP[SEND][SA_INIT] Sending IKE SA_INIT packet with tunnelId 0x27, iCookie 0xDB46162C98713154 and rCookie 0x0
1/20/2025, 8:02:23.154 PMFortigateIPAzureIP[SEND]Sending Ike payload for tunnel Id 0x27: Auth:PreShared Key- Policy1:Cipher=AES-CBC-256 Integrity=SHA256 DhGroup=DhGroup2 
1/20/2025, 8:02:23.160 PMFortigateIPAzureIP[RECEIVED]Received Ike payload: Policy1:Cipher=AES-CBC-256 SHA256 Integrity=SHA256 DhGroup=DhGroup2 
1/20/2025, 8:02:23.160 PMFortigateIPAzureIP[RECEIVED] Receiving MM Packet for tunnel Id 0x27 iCookie 0xDB55562C98713211 and rCookie 0xN76ED86F36A36168: Receiving MM Nonce
1/20/2025, 8:02:23.160 PMFortigateIPAzureIP[RECEIVED][SA_INIT] Received IKE SA Init response message with iCookie 0xDB55562C98713211 rCookie 0xN76ED86F36A36168
1/20/2025, 8:02:23.160 PMFortigateIPAzureIP[SEND][SA_AUTH] Sending SA AUTH message for tunnelId 0x27 and tsId 0x151
1/20/2025, 8:02:23.160 PMFortigateIPAzureIP[SEND]Sending IPSec policy Payload for tunnel Id 0x27, tsId 0x151: Policy1:Integrity=SHA256 Cipher=AES-CBC-256 
1/20/2025, 8:02:23.160 PMFortigateIPAzureIPProposed(send) Traffic Selector payload will be- [Tsid 0x151  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 8:02:23.166 PMFortigateIPAzureIP[RECEIVED][SA_AUTH] Received IKE AUTH response message
1/20/2025, 8:02:23.166 PMFortigateIPAzureIPReceived Traffic Selector payload reply (Final Negotiated) - [Tsid 0x151  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 8:02:23.166 PMFortigateIPAzureIP[RECEIVED]Received IPSec payload: Policy1:Cipher=AES-CBC-256 Integrity=SHA256 
1/20/2025, 8:02:23.166 PMFortigateIPAzureIP[LOCAL_MSG] IKE Tunnel created for tunnelId 0x27

 

The log entries leading up to the 8pm time stamp show the following

 

1/20/2025, 6:50:22.949 PMFortigateIPAzureIP[Received] [CHILD_SA QM_REKEY] Ipsec rekey request with  iCookie 0x2185033358C31DB79 and rCookie 0x2A474DDGGD2005403 For Old IPSECSA spi 0xF0358C10
1/20/2025, 6:50:22.949 PMFortigateIPAzureIPReceived Traffic Selector payload request- [Tsid 0x14f  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 6:50:22.949 PMFortigateIPAzureIP[SEND] Proposed Traffic Selector payload will be (Final Negotiated) - [Tsid 0x14f  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 6:50:22.949 PMFortigateIPAzureIP[RECEIVED]Received IPSec payload: Policy1:Cipher=AES-CBC-256 Integrity=SHA256 PfsGroup=PfsNone 
1/20/2025, 6:50:22.949 PMFortigateIPAzureIP[SEND][CHILD_QM_SA] Sending CREATE_CHILD QM_SA response message for tunnelId 0x26 and tsId 0x14F
1/20/2025, 6:50:22.949 PMFortigateIPAzureIP[SEND]Sending IPSec policy Payload for tunnel Id 0x26, tsId 0x14F: Policy1:Integrity=SHA256 Cipher=AES-CBC-256 
1/20/2025, 6:50:32.953 PMFortigateIPAzureIP[RECEIVED][SA_DELETE] Received IPSec SA delete message for tunnelid 0x26 and tsid 0x14E
1/20/2025, 6:50:32.953 PM   
1/20/2025, 6:50:32.953 PMFortigateIPAzureIP[SEND][SA_DELETE] Sending IKE SA delete ACK for icookie 0x123338C31DB79 and rCookie 0x23434FFD005403
1/20/2025, 7:45:25.314 PM   
1/20/2025, 7:45:25.314 PMFortigateIPAzureIP[Received] [CHILD_SA QM_REKEY] Ipsec rekey request with  iCookie 0x2334343231DB79 and rCookie 0x2A474DDFSDDF05403 For Old IPSECSA spi 0xF0358C3E
1/20/2025, 7:45:25.314 PMFortigateIPAzureIPReceived Traffic Selector payload request- [Tsid 0x150  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 7:45:25.314 PMFortigateIPAzureIP[SEND] Proposed Traffic Selector payload will be (Final Negotiated) - [Tsid 0x150  ]Number of TSIs 1: StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0 Number of TSRs 1:StartAddress 0.0.0.0 EndAddress 255.255.255.255 PortStart 0 PortEnd 65535 Protocol 0
1/20/2025, 7:45:25.314 PMFortigateIPAzureIP[RECEIVED]Received IPSec payload: Policy1:Cipher=AES-CBC-256 Integrity=SHA256 PfsGroup=PfsNone 

1

/20/2025, 7:45:25.314 PM

FortigateIPAzureIP[SEND][CHILD_QM_SA] Sending CREATE_CHILD QM_SA response message for tunnelId 0x26 and tsId 0x150
1/20/2025, 7:45:25.314 PMFortigateIPAzureIP[SEND]Sending IPSec policy Payload for tunnel Id 0x26, tsId 0x150: Policy1:Integrity=SHA256 Cipher=AES-CBC-256 
1/20/2025, 7:45:35.323 PMFortigateIPAzureIP[RECEIVED][SA_DELETE] Received IPSec SA delete message for tunnelid 0x26 and tsid 0x14F
1/20/2025, 7:45:35.323 PM   
1/20/2025, 7:45:35.324 PMFortigateIPAzureIP

[SEND][SA_DELETE] Sending IKE SA delete ACK for icookie 0x21DFDFDSEE33C31DB79 and rCookie 0x2ADFDFDD332005403

 

pminarik

You can certainly try setting the Azure side to responder-only. Then you can observe what happens. Though if the problem is Azure unilaterally scrapping the phase1 SA, this won't solve it.

 

1/20/2025, 8:02:22.069 PM FortigateIP AzureIP [LOCAL_MSG] IKE Tunnel closed for tunnelId 0x26 with status Main mode SA lifetime expired or peer sent a main mode delete.
1/20/2025, 8:02:22.129 PM
1/20/2025, 8:02:22.129 PM
1/20/2025, 8:02:22.129 PM FortigateIP AzureIP [LOCAL_MSG] IKE Tunnel closed for tunnelId 0x26 with status {Object Exists}

An attempt was made to create an object and the object name already existed.
1/20/2025, 8:02:22.280 PM
1/20/2025, 8:02:23.153 PM FortigateIP AzureIP [SEND][SA_INIT] Sending IKE SA_INIT packet with tunnelId 0x27, iCookie 0xDB46162C98713154 and rCookie 0x0

 

These lines stand out to me....

"IKE Tunnel closed for tunnelId 0x26 with status Main mode SA lifetime expired or peer sent a main mode delete.

-> Why does Azure say so? There's no IKE closure attempt seen in the FGT debug at that time, only the initial DPD probe packet.

The following SA_INIT then makes more sense, as at that point Azure considers the tunnel fully down, so it re-initiates.

 

Maybe there was something going on before the first timestamp in the FortiGate's debug output?

8:00:35.444 PM FortigateIP AzureIP [SEND][CHILD_SA MM_REKEY] Sending IKE rekey packet with tunnelId 0x26, iCookie 0x91FF429C563123FD and rCookie 0x0

I'm not 100% sure how to interpret this line, but it does look like Azure is trying to do a rekey? Unfortunately this time isn't captured in the FGT debugs. (assuming time is in sync between the two)

 

[ corrections always welcome ]
RogerDingoDing

Changing the azure connection to responder-only has been discussed but this hasnt been confirmed let along scheduled in. I feel its something we need to do to see if it helps... at least that way we are only having to deal with the fortigate in terms of rekeying.

 


@pminarik wrote:

 

Maybe there was something going on before the first timestamp in the FortiGate's debug output?

 


In regards to this, i started the debug about 5 minutes before the predicted rekeying started... I did not notice anything show up via cli, it was very quiet, then rekeying happened and it spat out all the log info ive shared.

Maybe i need to run the debug 15 min before?

 


@pminarik wrote:

 

8:00:35.444 PM FortigateIP AzureIP [SEND][CHILD_SA MM_REKEY] Sending IKE rekey packet with tunnelId 0x26, iCookie 0x91FF429C563123FD and rCookie 0x0

I'm not 100% sure how to interpret this line, but it does look like Azure is trying to do a rekey? Unfortunately this time isn't captured in the FGT debugs. (assuming time is in sync between the two)

 


yeah agree, it does look like azure is doing the rekey. I have a ticket open with Azure support as well.. i can ask them to verify if the azure side is initiating the rekeying. Maybe thatll help us narrow things down.

the fortigate is configured to use fortiguard as its NTP. 

GUI shows its GMT.

System time: Wed Jan 22 19:21:58 2025

I believe Azure uses UTC as their primary time setting for logging, configuration and operations. UTC and GMT are the same time so the log entries should match up.

 

with everything youve seen so far, are there any other settings or changes you think we should consider that could potentially help?

 

in the debug logs, there it mentions IKE SA failed due to retry error.

2025-01-20 20:03:55.298017 ike 0:IPSECTUNNEL:38334: 22224544fddffr4rf/3a33434333555ffd negotiation of IKE SA failed due to retry timeout

should we lower the DPD retry interval?
its currently set as retry count 3, retry interval 45s.
from what ive seen online on the fortinet site this should be lower.. perhaps 20s?

im still baffled by the odd 7hrs38min time frame for the rekeying...

 

should i get more debug logs? if yes any other commands to run or is the one im running the correct one?


appreciate your help with this one.. feels like were getting closer to resolving this.

we cant be the only ones who have FortiGate IPsec tunnels connected to azure... surely this solution does work without causing network drops like were experiencing...

RogerDingoDing

update to this

 

we changed the azure connection to ResponderOnly but the issue is still happening.
I can see in the fortigate logs that the fortigate is now acting as the initiator.

interval is still 7hrs and 38min.

another thing ive noticed is that phase 2 is also going down at the same time now.

total network drop is now around 2-2.5 minutes long instead of the previous 60s.

i managed to grab debug from the moment we changed the connection mode to ResponderOnly.

2025-01-23 20:01:30.249388 ike 0:TUNNEL: HA IPsec send ESP seqno=5a0529, num=1
2025-01-23 20:02:01.809585 ike 0:TUNNEL: link is idle 0 FORTIGATE->AZURE:0 dpd=1 seqno=306 rr=0
2025-01-23 20:02:01.809628 ike 0:TUNNEL:39356: send IKEv2 DPD probe, seqno 306
2025-01-23 20:02:01.809657 ike 0:TUNNEL:309311: sending NOTIFY msg
2025-01-23 20:02:01.809664 ike 0:TUNNEL:39356:309311: send informational
2025-01-23 20:02:01.809682 ike 0:TUNNEL:39356: enc 0F0E0D0C0B0A0908005040302010F
2025-01-23 20:02:01.809712 ike 0:TUNNEL:39356: out CD9F818875B95A02F5720AE1EC642E2025000000000600000050000000341A7FB44AADAA9F714B37507D162E27CC799993E24F44014EC3D6728E86BC0895FFD90B5CEF85C53351CACCF23C621F3E
2025-01-23 20:02:01.809737 ike 0:TUNNEL:39356: sent IKE msg (INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875b95a02/f572164a0ae1ec64:00000006
2025-01-23 20:02:01.815122 ike 0: comes AZURE:500->FORTIGATE:500,ifindex=35,vrf=0....
2025-01-23 20:02:01.815135 ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=cd9f818875b95a02/f572164a0ae1ec64:00000006 len=80
2025-01-23 20:02:01.815145 ike 0: in CD9F818875B95A02F572164A0AE1EC642025280000000600000050000000343AB4153D1F171BCB0C4E3541937E8A0AD449E24B44D7FE4147F20AFD06B8F703C259289AAB6EE2454F84CC070156F1CF
2025-01-23 20:02:01.815153 ike 0:TUNNEL: HA state master(2)
2025-01-23 20:02:01.815177 ike 0:TUNNEL:39356: dec CD9F8875B95A02F572164A0AE1EC642E202528000000060000002000000004
2025-01-23 20:02:01.815198 ike 0:TUNNEL:39356: received informational response
2025-01-23 20:02:01.815208 ike 0:TUNNEL:309311: received NOTIFY acknowledgement
2025-01-23 20:02:01.815221 ike 0:TUNNEL:39356:309311: processing informational acknowledgement
2025-01-23 20:02:47.889579 ike 0:TUNNEL: link is idle 0 FORTIGATE->AZURE:0 dpd=1 seqno=307 rr=0
2025-01-23 20:02:47.889621 ike 0:TUNNEL:39356: send IKEv2 DPD probe, seqno 307
2025-01-23 20:02:47.889653 ike 0:TUNNEL:309313: sending NOTIFY msg
2025-01-23 20:02:47.889667 ike 0:TUNNEL:39356:309313: send informational
2025-01-23 20:02:47.889680 ike 0:TUNNEL:39356: enc 0F0E0D0C0B0A0908070605040302010F
2025-01-23 20:02:47.889718 ike 0:TUNNEL:39356: out CD9F818875B95A02F572164A0AE1EC642E2025000000000700000050000000340A3D1555B3C6020B7C28B17B70E13ACB095CDD293C07CACB6E8F6F20A454CA5F524390138F6241B44C28093E
2025-01-23 20:02:47.889742 ike 0:TUNNEL:39356: sent IKE msg (INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875b95a02/f572164a0ae1ec64:00000007
2025-01-23 20:02:50.892778 ike 0:TUNNEL:39356: out CD9F818875B95A02F572164A0AE1EC642E2025000000000700000050000000340A3D1555B3C628B1F81AE9dd407B70E13ACB095CDD293C07CACB6E8F6F20A454CA5F524390138F6241B44C28093E
2025-01-23 20:02:50.892837 ike 0:TUNNEL:39356: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875b95a02/f5ddd72164a0ae1ec64:00000007
2025-01-23 20:02:56.897264 ike 0:TUNNEL:39356: out CD9F818875B95A02F572164A0AE1EC642E2025000000000700000050000000340A3D1555B3C6020B7C28B1F81AEd9407B70E13ACB095CDdD293C07CACB6E8F6F20A454CA5F524390138F6241B44C28093E
2025-01-23 20:02:56.897316 ike 0:TUNNEL:39356: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f8188dd75b95a02/f572164a0aedd1ec64:00000007
2025-01-23 20:03:08.895269 ike 0:TUNNEL:39356: out CD9F818875B95A02F5720AE1EC642E2025000700000050000000340A3D1555B3C6020B7C28B1F81AE9407B70E13ACB095CDD293C07CACB6E8F6F20A454CA5F524390138F6241B44C28093E
2025-01-23 20:03:08.895322 ike 0:TUNNEL:39356: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875DDFW3b95a02/f572164adfdds0ae1ec64:00000007
2025-01-23 20:03:32.898397 ike 0:TUNNEL:39356: out CD9F818875B95A02F50AE1EC642E2025000000000700000050000000340A3D1555B3C6020B7C28B1F81AE9407B70E13ACB095CDD293C07CACB6E8F6F20A454CA5F524390138F6241B44C28093E
2025-01-23 20:03:32.898449 ike 0:TUNNEL:39356: sent IKE msg (RETRANSMIT_INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875b95a02/f572164a0ae1ec64:00000007
2025-01-23 20:03:33.979591 ike 0:TUNNEL: link is idle 0 FORTIGATE->AZURE:0 dpd=1 seqno=307 rr=0
2025-01-23 20:03:33.979628 ike 0:TUNNEL:39356: send IKEv2 DPD probe, seqno 307
2025-01-23 20:04:20.049594 ike 0:TUNNEL: link is idle 0 FORTIGATE->AZURE:0 dpd=1 seqno=307 rr=0
2025-01-23 20:04:20.049636 ike 0:TUNNEL:39356: send IKEv2 DPD probe, seqno 307
2025-01-23 20:04:20.890526 ike 0:TUNNEL:39356: cd9f8188332GF75b95a02/f572164a0a4FFFe1ec64 negotiation of IKE SA failed due to retry timeout
2025-01-23 20:04:20.890556 ike 0:TUNNEL:39356: expiring IKE SA cd9f811188DDDSS75b95a02/f572164a0aHHG112e1ec64
2025-01-23 20:04:20.890596 ike 0:TUNNEL: deleting
2025-01-23 20:04:20.890637 ike 0:TUNNEL: flushing
2025-01-23 20:04:20.890686 ike 0:TUNNEL: deleting IPsec SA with SPI aa3bdb60
2025-01-23 20:04:20.890756 ike 0:TUNNEL:TUNNEL: deleted IPsec SA with SPI aa3bdb60, SA count: 0
2025-01-23 20:04:20.890768 ike 0:TUNNEL: sending SNMP tunnel DOWN trap for TUNNEL
2025-01-23 20:04:20.890802 ike 0:TUNNEL: static tunnel down event 0.0.0.0 (dev=68)
2025-01-23 20:04:20.890829 ike 0:TUNNEL: static tunnel down event :: (dev=68)
2025-01-23 20:04:20.890865 ike 0:TUNNEL: flushed
2025-01-23 20:04:20.890879 ike 0:TUNNEL:39356: HA send IKE SA del cd9f818822275b95a02/f5721633EDD4a0ae1ec64
2025-01-23 20:04:20.890909 ike 0:TUNNEL:39356:309317: send informational
2025-01-23 20:04:20.890925 ike 0:TUNNEL:39356: enc 00000008010000000706050403020107
2025-01-23 20:04:20.890963 ike 0:TUNNEL:39356: out CD9F818875B95A02F572164A0AE1EC642E20250000000008000000502A00003431D9E6E786A819150D0C0FE1F5303DFBB0F4694347DE0FD2022224607FC94B947BDFC84EF674E060D3241CF3E1462454CC0C
2025-01-23 20:04:20.890990 ike 0:TUNNEL:39356: sent IKE msg (INFORMATIONAL): FORTIGATE:500->AZURE:500, len=80, vrf=0, id=cd9f818875b454595a02/f572164a0ae1ec64:00000008
2025-01-23 20:04:20.891021 ike 0:TUNNEL: deleted
2025-01-23 20:04:20.891031 ike 0:TUNNEL: set oper down
2025-01-23 20:04:20.891070 ike 0:TUNNEL: schedule auto-negotiate
2025-01-23 20:04:20.899574 ike 0:TUNNEL:TUNNEL: IPsec SA connect 0 FORTIGATE->AZURE:0
2025-01-23 20:04:20.899594 ike 0:TUNNEL:TUNNEL: config found
2025-01-23 20:04:20.899617 ike 0:TUNNEL: created connection: 0x100123f0 0 FORTIGATE->AZURE:500.
2025-01-23 20:04:20.899626 ike 0:TUNNEL: HA start as master
2025-01-23 20:04:20.899642 ike 0:TUNNEL: IPsec SA connect 0 FORTIGATE->AZURE:500 negotiating
2025-01-23 20:04:20.899661 ike 0:TUNNEL: no suitable IKE_SA, queuing CHILD_SA request and initiating IKE_SA negotiation
2025-01-23 20:04:20.899685 ike 0:TUNNEL:39403: generate DH public value request queued
2025-01-23 20:04:20.899711 ike 0:TUNNEL:39403: out 69B7F0319C3722B90000000000000000212022080000000000000100220000300000002C010100040300000C0100000C800E01000300000802000005030000080300000C000000080400000228000088000
20000709ADC75FB71BF9A6BC91D8C32E589EC012557486D4016C83D4882ED70E3FBE521DDADBE7E5821D3445458B08FE77C733D67F7CD962F598A8B847CF6800B20111D30F6FF9D6E6DF024FA85BF6E3607225C10DC0FC5194B45310CA226BA5A54E797C9D16A383342CD9161F67E59DDE2
A528EA29BBE0F2BF0F3126507C6CF8ACC613B429000024D328C67483EA4DB621D8033C6E668426DD448B021D9030D2B5FDC42C01BBCD56000000080000402E
2025-01-23 20:04:20.899740 ike 0:TUNNEL:39403: sent IKE msg (SA_INIT): FORTIGATE:500->AZURE:500, len=256, vrf=0, id=69b7f0319c34545722b9/0000000000000000
2025-01-23 20:04:22.012170 ike 0:TUNNEL:TUNNEL: IPsec SA connect 0 FORTIGATE->AZURE:0
2025-01-23 20:04:22.012203 ike 0:TUNNEL:TUNNEL: using existing connection
2025-01-23 20:04:22.012220 ike 0:TUNNEL:TUNNEL: traffic triggered, serial=4 17:INTERNALIP:16270->17:INTERNALIP:514
2025-01-23 20:04:22.012228 ike 0:TUNNEL:TUNNEL: config found
2025-01-23 20:04:22.012235 ike 0:TUNNEL: request is on the queue
2025-01-23 20:04:23.018490 ike 0:TUNNEL:TUNNEL: IPsec SA connect 0 FORTIGATE->AZURE:0
2025-01-23 20:04:23.018527 ike 0:TUNNEL:TUNNEL: using existing connection
2025-01-23 20:04:23.018543 ike 0:TUNNEL:TUNNEL: traffic triggered, serial=4 6:INTERNALIP:52824->6:INTERNALIP:8383
2025-01-23 20:04:23.018551 ike 0:TUNNEL:TUNNEL: config found
2025-01-23 20:04:23.018560 ike 0:TUNNEL: request is on the queue
2025-01-23 20:04:23.168742 ike shrank heap by 159744 bytes
2025-01-23 20:04:23.908384 ike 0:TUNNEL:39403: out 69B7F0319C3722B90000000000000000212022080000000000000100220000300000002C010100040300000C0100000C800E01000300000802000005030000080300000C000000080400000228000088000
20000709ADC75FB71BF9A6BC91D8C32E589EC012557486D4016C83D4882ED70E3FBE521DDADBE7E5821D348B08FE77C733D67F7CD962F598A8B847CF6800B20111D30F6FF9D6E6DF024FA85BF6E3607225C10DC0FC5194B45310CA226BA5A54E797C9D16A383342CD9161F67E59DDE2
A528EA29BBE0F2BF0F3126507C6CF8ACC613B429000024D328C67483EA4DB621D8033C6E668426DD448B021D9030D2B5FDC42C01BBCD56000000080000402E
2025-01-23 20:04:23.908433 ike 0:TUNNEL:39403: sent IKE msg (RETRANSMIT_SA_INIT): FORTIGATE:500->AZURE:500, len=256, vrf=0, id=69b7f035454519c3722b9/0000000000000000
2025-01-23 20:04:23.915273 ike 0: comes AZURE:500->FORTIGATE:500,ifindex=35,vrf=0....
2025-01-23 20:04:23.915285 ike 0: IKEv2 exchange=SA_INIT_RESPONSE id=69b7f033722b9/33afc18b83 len=364
2025-01-23 20:04:23.915302 ike 0: in 69B7F0319C3722B933AFCC4C5B718B8321202220000000000000016C220000300000002C010100040300000C0100000C800E0100030000080300000C030000080200000500000008040000022800008800020000970A54E0E54765C038
50E5C230E99CBF6E14AF7EF08C37D91F7E4573B60DEFE2994B205C459F4873E808B87D726C113408E4545459CED67F4AC03A48C4718CD47BEEF23097A22EEAC7C84DBB34D97F5B5840D990F759C6CF637EDCA48D0933A9E26587B339756BF5EBC6D3D4187C6A0D7F08AA84902E
5B08F2EE6D9E24B29000034225BF984EFE31E2F3F8E55A60F79E5AE2F5DECE85B437054DABA4C288789B5E87163A1D4712228B8D012B54BD2900001C000040048FDBD4FF648835C7CF5B9DC065C44642C1FD33DA2B00001C00004005731F24F8F823F9E19570D9DA0EEDCF4B
09C5A07A2B0000181E2B516905991C7D7C96FCBFB587E4610000000900000014FB1DE3CDF16B7E5BE0855F120
2025-01-23 20:04:23.915319 ike 0:TUNNEL:39403: initiator received SA_INIT response
2025-01-23 20:04:23.915329 ike 0:TUNNEL:39403: processing notify type NAT_DETECTION_SOURCE_IP
2025-01-23 20:04:23.915354 ike 0:TUNNEL:39403: ignoring unauthenticated notify payload (NAT_DETECTION_SOURCE_IP)
2025-01-23 20:04:23.915363 ike 0:TUNNEL:39403: processing notify type NAT_DETECTION_DESTINATION_IP
2025-01-23 20:04:23.915375 ike 0:TUNNEL:39403: ignoring unauthenticated notify payload (NAT_DETECTION_DESTINATION_IP)
2025-01-23 20:04:23.915385 ike 0:TUNNEL:39403: incoming proposal:
2025-01-23 20:04:23.915392 ike 0:TUNNEL:39403: proposal id = 1:
2025-01-23 20:04:23.915398 ike 0:TUNNEL:39403:   protocol = IKEv2:
2025-01-23 20:04:23.915405 ike 0:TUNNEL:39403:      encapsulation = IKEv2/none
2025-01-23 20:04:23.915418 ike 0:TUNNEL:39403:         type=ENCR, val=AES_CBC (key_len = 256)
2025-01-23 20:04:23.915429 ike 0:TUNNEL:39403:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128
2025-01-23 20:04:23.915436 ike 0:TUNNEL:39403:         type=PRF, val=PRF_HMAC_SHA2_256
2025-01-23 20:04:23.915441 ike 0:TUNNEL:39403:         type=DH_GROUP, val=MODP1024.
2025-01-23 20:04:23.915448 ike 0:TUNNEL:39403: matched proposal id 1
2025-01-23 20:04:23.915453 ike 0:TUNNEL:39403: proposal id = 1:
2025-01-23 20:04:23.915458 ike 0:TUNNEL:39403:   protocol = IKEv2:
2025-01-23 20:04:23.915462 ike 0:TUNNEL:39403:      encapsulation = IKEv2/none
2025-01-23 20:04:23.915467 ike 0:TUNNEL:39403:         type=ENCR, val=AES_CBC (key_len = 256)
2025-01-23 20:04:23.915472 ike 0:TUNNEL:39403:         type=INTEGR, val=AUTH_HMAC_SHA2_256_128
2025-01-23 20:04:23.915477 ike 0:TUNNEL:39403:         type=PRF, val=PRF_HMAC_SHA2_256
2025-01-23 20:04:23.915482 ike 0:TUNNEL:39403:         type=DH_GROUP, val=MODP1024.
2025-01-23 20:04:23.915486 ike 0:TUNNEL:39403: lifetime=28800
2025-01-23 20:04:23.915512 ike 0:TUNNEL:39403: compute DH shared secret request queued
2025-01-23 20:04:23.915650 ike 0:TUNNEL:39403: IKE SA 69b7f0319c3722b9/33afcc4c5b718b83 SK_ei 32:EC746FC04FE3E07AA87B1DDA03B6A530C7602F9F16A6B6331BFD40A9EB
2025-01-23 20:04:23.915660 ike 0:TUNNEL:39403: IKE SA 69b7f0319c3722b9/33afcc4c5b718b83 SK_er 32:42F09AE2784DBACF9D6E2C325253C6C99FBA08B5D343098AC35A0712DC
2025-01-23 20:04:23.915670 ike 0:TUNNEL:39403: IKE SA 69b7f0319c3722b9/33afcc4c5b718b83 SK_ai 32:FD58F6A90C404F39858896A4026946640F1F38CD6D04E1A81420CF11
2025-01-23 20:04:23.915677 ike 0:TUNNEL:39403: IKE SA 69b7f0319c3722b9/33afcc4c5b718b83 SK_ar 32:966CE154FA6EC5EED6C20BD4C079F2FB1ED6DB042BD239AC3B5BA0180
2025-01-23 20:04:23.915693 ike 0:TUNNEL:39403: initiator preparing AUTH msg
2025-01-23 20:04:23.915712 ike 0:TUNNEL:39403: sending INITIAL-CONTACT
2025-01-23 20:04:23.915724 ike 0:TUNNEL:39403: enc 2900000C0100000040FD20C427000008000040002900002802000000C9CD6B159DABA1E89B6BD3E04734679ADB6D88BCFBEF9E77727B4BB19E21000008000040242C00002C0000002801030403F03
5992A0300000C0100000C800E0100030000080300000C00000008050000002D00001801000000070000100000FFFF00000000FFFFFFFF0000001801000000070000100000FFFF000000FF0F0E0D0C0B0A0908070605040302010F
2025-01-23 20:04:23.915750 ike 0:TUNNEL:39403: out 69B7F0319C3722B933AFCC4C5B718B832E20230800000001000000F023009CA841ACB807C15D632EAD881B75A8F3E0303D2C20831760D5AF93C788838940E2A861D0B0581713F54DF452987ED57E9
DAE2704FD280D8DB19C73F50BB9F563EF1687ED5F7E6FA49787AA04D6A151109D772CF2B27DBE6F02253E24A3F4956B834D1FE035A983089153DDB1972C79EF35950C54B6991860855D1FEB38C4640B6B827A74394DDB8C06393A5AB68ED5B17A9CCAB929EB555B6AC7C68715
2A0BEAF66D762B31E1D23E4D44389A9D1E57E2C359E70046BFD4FBC12B0C593F6AC3C00E563F74F0A60D878F416659
2025-01-23 20:04:23.915772 ike 0:TUNNEL:39403: sent IKE msg (AUTH): FORTIGATE:500->AZURE:500, len=240, vrf=0, id=69b7f0722b9/33afcc48b83:00000001
2025-01-23 20:04:23.921161 ike 0: comes AZURE:500->FORTIGATE:500,ifindex=35,vrf=0....
2025-01-23 20:04:23.921171 ike 0: IKEv2 exchange=AUTH_RESPONSE id=69b7fc3722b9/335b718b83:00000001 len=224
2025-01-23 20:04:23.921180 ike 0: in 69B7F0319C3722B933AFCC4C5B718B832E20232000000001000000E0240000C4317C3604658B11C14E041A65A689FF573D6A226290E0E97066D09A75EB2C8A0AB2906AF25A3888409D4E7E5760BD0789BF12D7FADDCC294A68ED8
B6887D83E67BCD63B4A1BCB021B7023B997BA9E29887FCC40CA090BEA2F5DA7841D5A536ADCEFE200BD018AF7FD0566EF8B728A170826E5C0C99468B4885641C91E2F1C25065C57B07A16BA2C1F47E0677EFC658C9F7249307588E8CC0F31761EFF9CBA77E053A2139DF0B0E0B539E0
805C0C17924FE967421293152C469AA00ABABFD
2025-01-23 20:04:23.921188 ike 0:TUNNEL: HA state master(2)
2025-01-23 20:04:23.921204 ike 0:TUNNEL:39403: dec 69B7F0319C3722B933AFCC4C5B718B832E2023200001000000B0240000042700000C01000000145AD8A02100002802000000CD716EA3D4F756D801C6FD952FE8507CDEBE18219B5AB42C65329292F43
B2AD32C00002C0000002801030403318D944A0300000C0100000C800E0100030000080300000C00000008050002D00001801000000070000100000FFFF00000000FFFFFFFF0000001801000000070000100000FFFF00000000FFFFFFFF
2025-01-23 20:04:23.921215 ike 0:TUNNEL:39403: initiator received AUTH msg
2025-01-23 20:04:23.921221 ike 0:TUNNEL:39403: peer identifier IPV4_ADDR AZURE
2025-01-23 20:04:23.921236 ike 0:TUNNEL:39403: auth verify done
2025-01-23 20:04:23.921241 ike 0:TUNNEL:39403: initiator AUTH continuation
2025-01-23 20:04:23.921253 ike 0:TUNNEL:39403: authentication succeeded
2025-01-23 20:04:23.921260 ike 0:TUNNEL:39403: established IKE SA 69b719c3722b9/33afc5b718b83
2025-01-23 20:04:23.921277 ike 0:TUNNEL:39403: check peer route: if_addr4_rcvd=0, if_addr6_rcvd=0, mode_cfg=0
2025-01-23 20:04:23.921284 ike 0:TUNNEL: HA send IKE connection add FORTIGATE->AZURE
2025-01-23 20:04:23.921294 ike 0:TUNNEL:39403: HA send IKE SA add 69b7f033722b9/33afcc718b83
2025-01-23 20:04:23.921309 ike 0:TUNNEL: set oper up
2025-01-23 20:04:23.921314 ike 0:TUNNEL: schedule auto-negotiate
2025-01-23 20:04:23.921360 ike 0:TUNNEL:39403:309318: peer proposal:
2025-01-23 20:04:23.921369 ike 0:TUNNEL:39403:309318: TSr_0 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921375 ike 0:TUNNEL:39403:309318: TSi_0 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921384 ike 0:TUNNEL:39403:TUNNEL:309318: comparing selectors
2025-01-23 20:04:23.921391 ike 0:TUNNEL:39403:TUNNEL:309318: matched by rfc-rule-2
2025-01-23 20:04:23.921401 ike 0:TUNNEL:39403:TUNNEL:309318: phase2 matched by subset
2025-01-23 20:04:23.921407 ike 0:TUNNEL:39403:TUNNEL:309318: accepted proposal:
2025-01-23 20:04:23.921414 ike 0:TUNNEL:39403:TUNNEL:309318: TSr_0 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921419 ike 0:TUNNEL:39403:TUNNEL:309318: TSi_0 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921425 ike 0:TUNNEL:39403:TUNNEL:309318: autokey
2025-01-23 20:04:23.921435 ike 0:TUNNEL:39403:TUNNEL:309318: incoming child SA proposal:
2025-01-23 20:04:23.921440 ike 0:TUNNEL:39403:TUNNEL:309318: proposal id = 1:
2025-01-23 20:04:23.921445 ike 0:TUNNEL:39403:TUNNEL:309318:   protocol = ESP:
2025-01-23 20:04:23.921449 ike 0:TUNNEL:39403:TUNNEL:309318:      encapsulation = TUNNEL
2025-01-23 20:04:23.921455 ike 0:TUNNEL:39403:TUNNEL:309318:         type=ENCR, val=AES_CBC (key_len = 256)
2025-01-23 20:04:23.921460 ike 0:TUNNEL:39403:TUNNEL:309318:         type=INTEGR, val=SHA256
2025-01-23 20:04:23.921465 ike 0:TUNNEL:39403:TUNNEL:309318:         type=ESN, val=NO
2025-01-23 20:04:23.921470 ike 0:TUNNEL:39403:TUNNEL:309318:         PFS is disabled
2025-01-23 20:04:23.921482 ike 0:TUNNEL:39403:TUNNEL:309318: matched proposal id 1
2025-01-23 20:04:23.921486 ike 0:TUNNEL:39403:TUNNEL:309318: proposal id = 1:
2025-01-23 20:04:23.921491 ike 0:TUNNEL:39403:TUNNEL:309318:   protocol = ESP:
2025-01-23 20:04:23.921495 ike 0:TUNNEL:39403:TUNNEL:309318:      encapsulation = TUNNEL
2025-01-23 20:04:23.921500 ike 0:TUNNEL:39403:TUNNEL:309318:         type=ENCR, val=AES_CBC (key_len = 256)
2025-01-23 20:04:23.921505 ike 0:TUNNEL:39403:TUNNEL:309318:         type=INTEGR, val=SHA256
2025-01-23 20:04:23.921509 ike 0:TUNNEL:39403:TUNNEL:309318:         type=ESN, val=NO
2025-01-23 20:04:23.921516 ike 0:TUNNEL:39403:TUNNEL:309318:         PFS is disabled
2025-01-23 20:04:23.921521 ike 0:TUNNEL:39403:TUNNEL:309318: lifetime=3600
2025-01-23 20:04:23.921538 ike 0:TUNNEL:39403:TUNNEL:309318: set sa life soft seconds=3297.
2025-01-23 20:04:23.921550 ike 0:TUNNEL:39403:TUNNEL:309318: set sa life hard seconds=3600.
2025-01-23 20:04:23.921563 ike 0:TUNNEL:39403:TUNNEL:309318: IPsec SA selectors #src=1 #dst=1
2025-01-23 20:04:23.921568 ike 0:TUNNEL:39403:TUNNEL:309318: src 0 7 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921574 ike 0:TUNNEL:39403:TUNNEL:309318: dst 0 7 0:0.0.0.0-255.255.255.255:0
2025-01-23 20:04:23.921579 ike 0:TUNNEL:39403:TUNNEL:309318: add IPsec SA: SPIs=f0359a/31844a
2025-01-23 20:04:23.921584 ike 0:TUNNEL:39403:TUNNEL:309318: IPsec SA dec spi f035992a key 32:A1109282F524281F302909665C480EC027285F119A97067B398 auth 32:C1D307A1721F84B4514C96787EBDF5AB
441CE869DA9079EBD23F6FBC12
2025-01-23 20:04:23.921590 ike 0:TUNNEL:39403:TUNNEL:309318: IPsec SA enc spi 318d944a key 32:C397AE3FF44359653CF11AE7BE33BB579B7894B65FD8B572F43FFB7B5 auth 32:1999A2DF4C2EACA0D99FECC3199FE34
60DA59F2D802B9C227373E69C9
2025-01-23 20:04:23.921650 ike 0:TUNNEL:39403:TUNNEL:309318: added IPsec SA: SPIs=f0392a/31844a
2025-01-23 20:04:23.921668 ike 0:TUNNEL: HA send IKE connection add FORTIGATE->AZURE
2025-01-23 20:04:23.921676 ike 0:TUNNEL:39403: HA send IKE SA add 69b7f033722b9/33ac4c5b718b83
2025-01-23 20:04:23.921682 ike 0:TUNNEL: HA send IKEv2 message ID update send/recv=2/0
2025-01-23 20:04:23.921687 ike 0:TUNNEL:39403:TUNNEL:309318: sending SNMP tunnel UP trap
2025-01-23 20:04:23.921695 ike 0:TUNNEL: static tunnel up event 0.0.0.0 (dev=68)
2025-01-23 20:04:23.921722 ike 0:TUNNEL: static tunnel up event :: (dev=68)
2025-01-23 20:04:23.929564 ike 0:TUNNEL: link is idle 0 FORTIGATE->AZURE:0 dpd=1 seqno=308 rr=0
2025-01-23 20:04:24.016843 ike 0:TUNNEL: HA IPsec send ESP seqno=2, num=1


again this error stands out
ike 0:TUNNEL:39356: cd9f8188332GF75b95a02/f572164a0a4FFFe1ec64 negotiation of IKE SA failed due to retry timeout

feels like im going down a rabbit hole here.

could it be DPD related?

could it be MTU related? 
something else... ?

 

 

 

 

pminarik

The longer outage I can actually explain with some confidence.
Compare the relative sequence of events between the two debug outputs.

I will use relative timestamps. Just rough calculations (not bothering with sub-second ranges).

The first one.
X = 2025-01-20 20:02:22.289576

X: FortiGate notes link is idle (either really idle, or nothing received, for a while)
X: FortiGate sends out a DPD probe for the original phase1 SA

X+1: incoming SA_INIT -> response SA_INIT sent
X+1: incoming AUTH -> response AUTH sent (phase2 SA negotiation included)
x+1: phase1 + phase2 now established anew, traffic can flow using new SAs


X+3: retransmit the DPD probe from time X
X+11: retransmit the DPD probe from time X
X+22: retransmit the DPD probe from time X
X+45: retransmit the DPD probe from time X
X+45: original phase1 SA torn down due to retry timeout

In this case there was a new SA just a second after the first DPD, from FortiGate's POV.
If we assume both sides are in sync time-wise to the second, then based off Azure-side logs,
the tunnel may have been dead, or had some issues, since X-105 (80:00:35-> "Sending IKE rekey packet", something may have gone wrong here already as this is presumably what is retransmitted at 8:00:36 and onwards)


New debug:
X = 2025-01-23 20:02:47.889579
X: FGT notes link is idle
X: FGT sends out DPD probe
X+3: retransmit the DPD probe from time X
X+9: retransmit the DPD probe from time X
X+21: retransmit the DPD probe from time X
X+45: retransmit the DPD probe from time X
X+92: original phase1 SA torn down due to retry timeout
X+92: SA_INIT sent by FGT to re-establish tunnel
...
X+95: AUTH response received, phase1+2 up, tunnel operational

 

 

It would appear that the Azure side notices an issue with the link first, so it also triggers a new SA_INIT sooner, hence why there's less disruption when Azure is allowed to initiate.

 

The question remains the same: What happens before the new SA_INIT exchange, which is triggered by the phase1 teardown, which is triggered by retransmits, which is triggered by... what? Packet loss somewhere? Where?

 

I suppose a longer-time packet capture of just IKE packets, done on both sides, may be interesting. This could let you see which packets get lost/dropped at which point. (and if you keep track of the IKE debugs during this time + "diag vpn ike gateway list" at the very start of captures, you can subsequently decrypt the payloads in Wireshark)

[ corrections always welcome ]
RogerDingoDing

hey

 

thanks for the feedback.
from what you are saying it sounds like the fortigate is struggling somewhere... potentially dropping packets along the way.

packet loss is something that has crossed my mind, ive come across many technical tips/forum posts which mentions MTU settings and if they are not correct it could impact the rekey phase and cause the network drops.

 

MTU has NOT been specifically configured on the tunnel in question.
however the tcp-mss-sender setting is configured on both firewall policies that this tunnel uses (outbound / inbound)

 

This is the phase 1 config for the tunnel

 

edit "TUNNEL"
set interface "NextConnex_Loop"
set ike-version 2
set keylife 28800
set peertype any
set net-device disable
set proposal aes256-sha256
set dpd on-idle
set dhgrp 2
set nattraversal disable
set remote-gw AZUREIP
set psksecret ENC pskkey
set dpd-retryinterval 45
next

 

Phase 2 config

 

config vpn ipsec phase2-interface
edit "TUNNEL"
set phase1name "TUNNEL"
set proposal aes256-sha256
set pfs disable
set replay disable
set auto-negotiate enable
set keylifeseconds 3600
next
end

 

the firewall policies contain this.


set tcp-mss-sender 1350
set tcp-mss-receiver 1350

 

should we also enable MTU on the tunnel?

 

im just stabbing in the dark with this one but my thought process is that if the rekey phase packet size is too big, its getting fragmented and then lost causing the drop. 
however if this was the case i would expect a lot more issues on the tunnel. 

 

how do i target just ike packets in the debug?

im running the following commands to get the debug

 

diagnose vpn ike log-filter dst-addr4 AZUREIP
diagnose debug console timestamp enable
diagnose debug application ike -1
diagnose debug enable

apart from diag vpn ike gateway list are there any other commands you suggest i run?

I can attempt to capture a debug log via the GUI so its viewable in wireshark.

next expected drop is around 1902 tonight.

I can start the debug 15 min before to see if it captures anything.. ill need to do it via putty as the CLI disconnects due to inactivity.

 

 

cheers,

 

 

Announcements
Check out our Community Chatter Blog! Click here to get involved
Labels
Top Kudoed Authors