IPsec trouble disconnection between PFsense and FortiGate

Syo94 · Dec 29, 2023, 9:20 AM

Hi,

We are experiencing issues with an IPsec site-to-site connection involving between PFSense and FortiGate.

There are frequent disconnections, brief interruptions (microcuts), and occasional instances where we need to manually bring down and then bring up the IPsec connection.

Please find the log below. Could you please review it and provide assistance?

Thanks/

Here link to PFSense Log : https://file.io/L7ethUdsI0yi

Fortinet Log : https://file.io/tNUFB31RGJD4

Syo94 · Dec 30, 2023, 8:09 AM

Here link to PFSense Log : https://pastebin.com/BCj7HfCz

Fortinet Log : https://pastebin.com/Vj0qvePA

Konstanti · Dec 31, 2023, 3:35 PM

@synomega

Hi
Most likely, in your case, the problem comes from the Fortigate device. When updating phase-2 keys, this device, for some unknown reason, sends a message about deleting a new SA instead of a message about creating a new SA

This is an example of the correct behavior of Fortigate (I removed the excess)

Dec 28 12:45:05 charon 24256 11[KNL] creating rekey job for CHILD_SA ESP/0x9cf7e8e4/178.208.16.121
Dec 28 12:45:05 charon 24256 11[IKE] <con1|5> establishing CHILD_SA con1{517} reqid 3
Dec 28 12:45:05 charon 24256 11[CHD] <con1|5> CHILD_SA con1{512} state change: INSTALLED => REKEYING
Dec 28 12:45:05 charon 24256 11[ENC] <con1|5> generating CREATE_CHILD_SA request 25 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
Dec 28 12:45:05 charon 24256 11[NET] <con1|5> sending packet: from xxxx.xxxxx.68.36[500] to xxxx.xxxx.16.121[500] (512 bytes)
Dec 28 12:45:05 charon 24256 11[NET] <con1|5> received packet: from xxxx.xxxx.16.121[500] to xxxx.xxxx.68.36[500] (464 bytes)
Dec 28 12:45:05 charon 24256 11[ENC] <con1|5> parsed CREATE_CHILD_SA response 25 [ SA No KE TSi TSr ]

and this is an example of incorrect behavior of Fortigate (I removed the excess)

date=2023-12-28 time=12:45:57 eventtime=1703763957728246989 tz="+0100" logid="0101037135" type="event" subtype="vpn" level="notice" vd="root" logdesc="IPsec phase 2 SA deleted" msg="delete IPsec phase 2 SA" action="delete_ipsec_sa" remip=XXX.XXX.68.36 locip=XXX.XXXX.16.121 remport=0 locport=500 outintf="wan" cookies="bfac45f2598e85b8/d173420f8214edfb" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="VPN vers Pf" in_spi="ca9c4a8e" out_spi="9cf7e8e6"

Dec 28 12:45:57 charon 24256 16[KNL] creating rekey job for CHILD_SA ESP/0xca9c4a8e/XXX.XXX.68.36
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> establishing CHILD_SA con1{519} reqid 3
Dec 28 12:45:57 charon 24256 07[CHD] <con1|5> CHILD_SA con1{514} state change: INSTALLED => REKEYING
Dec 28 12:45:57 charon 24256 07[ENC] <con1|5> generating CREATE_CHILD_SA request 27 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]
Dec 28 12:45:57 charon 24256 07[NET] <con1|5> sending packet: from xxxx.xxxxx.68.36[500] to xxxx.xxxx.16.121[500] (512 bytes)
Dec 28 12:45:57 charon 24256 16[NET] <con1|5> received packet: from xxxx.xxxx.16.121[500] to xxxx.xxxxx.68.36[500] (80 bytes)
Dec 28 12:45:57 charon 24256 16[ENC] <con1|5> parsed INFORMATIONAL request 3 [ D ]
Dec 28 12:45:57 charon 24256 16[IKE] <con1|5> received DELETE for ESP CHILD_SA with SPI 9cf7e8e6

as a result, a collision occurs

Dec 28 12:45:57 charon 24256 16[IKE] <con1|5> detected CHILD_REKEY collision with CHILD_DELETE

which leads to a problem as a result

Dec 28 12:45:57 charon 24256 07[CHD] <con1|5> CHILD_SA con1{519} state change: INSTALLING => INSTALLED
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> CHILD_SA rekey/delete collision, deleting redundant child con1{519}
Dec 28 12:45:57 charon 24256 07[CHD] <con1|5> CHILD_SA con1{519} state change: INSTALLED => REKEYED
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> reinitiating already active tasks
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> CHILD_REKEY task
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> closing CHILD_SA con1{519} with SPIs ca7c9b0e_i (0 bytes) 9cf7e8eb_o (0 bytes) and TS 10.0.0.0/16|/0 === 192.168.1.0/24|/0
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> sending DELETE for ESP CHILD_SA with SPI ca7c9b0e
Dec 28 12:45:57 charon 24256 07[CHD] <con1|5> CHILD_SA con1{519} state change: REKEYED => DELETING
Dec 28 12:45:57 charon 24256 07[ENC] <con1|5> generating INFORMATIONAL request 28 [ D ]
Dec 28 12:45:57 charon 24256 07[NET] <con1|5> sending packet: from xxxx.xxxx.68.36[500] to xxxx.xxxx.16.121[500] (80 bytes)
Dec 28 12:45:57 charon 24256 07[NET] <con1|5> received packet: from xxxx.xxxx.16.121[500] to xxxx.xxxx.68.36[500] (80 bytes)
Dec 28 12:45:57 charon 24256 07[ENC] <con1|5> parsed INFORMATIONAL response 28 [ D ]
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> received DELETE for ESP CHILD_SA with SPI 9cf7e8eb
Dec 28 12:45:57 charon 24256 07[IKE] <con1|5> CHILD_SA closed
Dec 28 12:45:57 charon 24256 07[CHD] <con1|5> CHILD_SA con1{519} state change: DELETING => DELETED

as a result, you log into the PF WEB interface to see what's going on

Dec 28 12:47:52 charon 24256 15[CFG] vici client 1030 connected
Dec 28 12:47:52 charon 24256 16[CFG] vici client 1030 registered for: list-sa
Dec 28 12:47:52 charon 24256 15[CFG] vici client 1030 requests: list-sas
Dec 28 12:47:52 charon 24256 15[CFG] vici client 1030 disconnected
Dec 28 12:52:52 charon 24256 06[CFG] vici client 1031 connected
Dec 28 12:52:52 charon 24256 14[CFG] vici client 1031 registered for: list-sa
Dec 28 12:52:52 charon 24256 06[CFG] vici client 1031 requests: list-sas
Dec 28 12:52:52 charon 24256 14[CFG] vici client 1031 disconnected

maybe this link will help

https://github.com/strongswan/strongswan/discussions/1463?ysclid=lqtm5m7368997191818

michmoor · Jan 2, 2024, 4:32 AM

Can you increase the verbosity of the IPsec logs on the pfsense side? Almost seems like PFS isnt enabled on one side but i cant make heads or tails from the logs.

michmoor · Jan 2, 2024, 4:37 AM

Actually.................

Traffic selectors dont match.

Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> proposing traffic selectors for us:
Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> 10.0.0.0/16|/0
Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> 10.0.0.0/16|/0
Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> proposing traffic selectors for other:
Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> 192.168.1.0/24|/0
Dec 28 12:45:57	charon	24256	07[CFG] <con1|5> 10.212.134.0/24|/0

With IPsec the best way to make sure IPsec tunnels stay up and come up the first time is to make sure the configurations are mirror configs of each other. I can tell just from your logs they are not.

planedrop · Jan 2, 2024, 11:10 PM

Yeah like @michmoor is mentioning, I'd double check the config on both sides for Phase 1 and 2 and be sure they are identical.

If that still doesn't work then I'd dig deeper on the deleting SA issue mentioned by @Konstanti

Might also be worth checking to be sure the Fortigate is fully updated so there isn't a chance for some old bug.