Messages

@Isabella: I really thought that I had tried every possible config, but it seems that I missed "Start action: Trap+Start". I reused the new IPSec connections, set this option, and now the tunnel stays up.
Thank you very much!

I set "Start action: Trap+Start" on both child SAs and that seems to have helped, has been up for nearly 90h now.

I'll try that!

Due to my cross posting and further tests, I tried the old IPSec legacy mode and discovered that it is stable with this mode.
So there seems to be an issue with re-keying and the new mode in combination with a Fortigate firewall.
Logs are in my cross posting (won't "spam" this forum too).
Any ideas?

cross posting this to https://community.fortinet.com/t5/Support-Forum/Unstable-IPSec-tunnel-between-Fortigate-and-OpnSense/td-p/368314

Update: I did capture the debug log from the Fortigate side. There was a second VPN tunnel connection in the log file, I tried to clean up the log as good as possible. Maybe a hint in there?
During the capture the tunnel went up again without any changes on both sides.

Code Select Expand

ike V=root:0: comes yyy.yyy.yyy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=65....
ike V=root:0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=8b79c9b890913093/b8eae4473c0f280c:0000055f len=65
ike 0: in 8B79C9B890913093B8EAE4473C0F280C2E2025280000055F00000041000000252B6F3DC4FFE009C836B28EE993C0B3A6F74666DC169E00A0D21A009E4627107FA4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: comes yyy.yyy.yyy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=65....
ike V=root:0: IKEv2 exchange=INFORMATIONAL id=8b79c9b890913093/b8eae4473c0f280c:000004d8 len=65
ike 0: in 8B79C9B890913093B8EAE4473C0F280C2E202508000004D80000004100000025B369463700A681393EB60A786B5EBA04956DFC3DFDCD2D8FC4DE42C0B320AE49ED
ike :shrank heap by 159744 bytes
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: unknown SPI e8e6a44f 5 yyy.yy.yy.yy:0->xx.xx.xx.xxx
ike V=root:0:: send HA sync query conn scope=3 mode=4
ike V=root:0: comes yyy.yy.yy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=456....
ike V=root:0: IKEv2 exchange=SA_INIT id=ce13113404bcd448/0000000000000000 len=456
ike 0: in CE13113404BCD44800000000000000002120220800000000000001C82200002800000024010100030300000C01000014800E01000300000802000007000000080400000E28000108000E0000DC45753108B4B2BF1E0119462ACF7EC02A56779D93CEDDF3712C87D1F636D096A34DE6590FB5A90BD23BAFD82DBAC96D6F914480C3070D69E8FF16992B853C94977A029A8E16FC8E99ABEE39FAFB0CF4FAB5D5A5B48AB0FF631667914EFEB6360C159DCD44EFEACA96B55809E295003B55E9E49E1A7104F7A4ADDF7039E6FC4DBC0180A7F4E43B455E9D87AD868C692660F1BF7E00558BCB7DF159D4A9CCE029DE4081B41DEE09471937F5CDBE5E06E5F3EA1C954403AEFDA77E5148E38FA72179E483F3FC1A01A5D1F8AF33FC90791490CF1A7DDDA8F565E99470B89BD48D1748C2E3630EDC6064E81114DDF9F9DF0154A0CAB4CA29432BB035D0D4EF03048729000024323FD388A59CB881AF296486170B94B131F7473B926EEAC62EB91B52B0CD09832900001C00004004DDE6F3B40A1388289EC3B8E46C1A16095CAFAA362900001C00004005EC405F0532DC186FBEDE0C9A7B2B7993BB25E905290000080000402E290000100000402F00020003000400050000000800004016
ike V=root:0:ce13113404bcd448/0000000000000000:424: responder received SA_INIT msg
ike V=root:0:ce13113404bcd448/0000000000000000:424: received notify type NAT_DETECTION_SOURCE_IP
ike V=root:0:ce13113404bcd448/0000000000000000:424: received notify type NAT_DETECTION_DESTINATION_IP
ike V=root:0:ce13113404bcd448/0000000000000000:424: received notify type FRAGMENTATION_SUPPORTED
ike V=root:0:ce13113404bcd448/0000000000000000:424: received notify type SIGNATURE_HASH_ALGORITHMS
ike V=root:0:ce13113404bcd448/0000000000000000:424: received notify type 16406
ike V=root:0:ce13113404bcd448/0000000000000000:424: ignoring unauthenticated notify payload (16406)
ike V=root:0:ce13113404bcd448/0000000000000000:424: incoming proposal:
ike V=root:0:ce13113404bcd448/0000000000000000:424: proposal id = 1:
ike V=root:0:ce13113404bcd448/0000000000000000:424:   protocol = IKEv2:
ike V=root:0:ce13113404bcd448/0000000000000000:424:      encapsulation = IKEv2/none
ike V=root:0:ce13113404bcd448/0000000000000000:424:         type=ENCR, val=AES_GCM_16 (key_len = 256)
ike V=root:0:ce13113404bcd448/0000000000000000:424:         type=PRF, val=PRF_HMAC_SHA2_512
ike V=root:0:ce13113404bcd448/0000000000000000:424:         type=DH_GROUP, val=MODP2048.
ike V=root:0: cache rebuild start
ike V=root:0:xxxx_yyyy: sending DNS request for remote peer yyyyyyyy.yyyyyy.yyy
ike V=root:0: send IPv4 DNS query : yyyyyyyy.yyyyyy.yyy
ike V=root:0: cache rebuild done
ike V=root:0:ce13113404bcd448/0000000000000000:424: no proposal chosen
ike V=root:Negotiate SA Error: [11895]
ike V=root:0: DNS response received for remote gateway yyyyyyyy.yyyyyy.yyy
ike V=root:0: DNS yyyyyyyy.yyyyyy.yyy -> yyy.yy.yy.yy
ike V=root:0:xxxx_yyyy: 'yyyyyyyy.yyyyyy.yyy' resolved to yyy.yy.yy.yy
ike V=root:0:xxxx_yyyy: set remote-gw yyy.yy.yy.yy
ike V=root:0: comes yyy.yy.yy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=456....
ike V=root:0: IKEv2 exchange=SA_INIT id=ce13113404bcd448/0000000000000000 len=456
ike 0: in CE13113404BCD44800000000000000002120220800000000000001C82200002800000024010100030300000C01000014800E01000300000802000007000000080400000E28000108000E0000DC45753108B4B2BF1E0119462ACF7EC02A56779D93CEDDF3712C87D1F636D096A34DE6590FB5A90BD23BAFD82DBAC96D6F914480C3070D69E8FF16992B853C94977A029A8E16FC8E99ABEE39FAFB0CF4FAB5D5A5B48AB0FF631667914EFEB6360C159DCD44EFEACA96B55809E295003B55E9E49E1A7104F7A4ADDF7039E6FC4DBC0180A7F4E43B455E9D87AD868C692660F1BF7E00558BCB7DF159D4A9CCE029DE4081B41DEE09471937F5CDBE5E06E5F3EA1C954403AEFDA77E5148E38FA72179E483F3FC1A01A5D1F8AF33FC90791490CF1A7DDDA8F565E99470B89BD48D1748C2E3630EDC6064E81114DDF9F9DF0154A0CAB4CA29432BB035D0D4EF03048729000024323FD388A59CB881AF296486170B94B131F7473B926EEAC62EB91B52B0CD09832900001C00004004DDE6F3B40A1388289EC3B8E46C1A16095CAFAA362900001C00004005EC405F0532DC186FBEDE0C9A7B2B7993BB25E905290000080000402E290000100000402F00020003000400050000000800004016
ike V=root:0:ce13113404bcd448/0000000000000000:425: responder received SA_INIT msg
ike V=root:0:ce13113404bcd448/0000000000000000:425: received notify type NAT_DETECTION_SOURCE_IP
ike V=root:0:ce13113404bcd448/0000000000000000:425: received notify type NAT_DETECTION_DESTINATION_IP
ike V=root:0:ce13113404bcd448/0000000000000000:425: received notify type FRAGMENTATION_SUPPORTED
ike V=root:0:ce13113404bcd448/0000000000000000:425: received notify type SIGNATURE_HASH_ALGORITHMS
ike V=root:0:ce13113404bcd448/0000000000000000:425: received notify type 16406
ike V=root:0:ce13113404bcd448/0000000000000000:425: ignoring unauthenticated notify payload (16406)
ike V=root:0:ce13113404bcd448/0000000000000000:425: incoming proposal:
ike V=root:0:ce13113404bcd448/0000000000000000:425: proposal id = 1:
ike V=root:0:ce13113404bcd448/0000000000000000:425:   protocol = IKEv2:
ike V=root:0:ce13113404bcd448/0000000000000000:425:      encapsulation = IKEv2/none
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=ENCR, val=AES_GCM_16 (key_len = 256)
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=PRF, val=PRF_HMAC_SHA2_512
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=DH_GROUP, val=MODP2048.
ike V=root:0: cache rebuild start
ike V=root:0:xxxx_yyyy: local:xx.xx.xx.xxx, remote:yyy.yy.yy.yy
ike V=root:0:xxxx_yyyy: cached as static-ddns.
ike V=root:0: cache rebuild done
ike V=root:0:ce13113404bcd448/0000000000000000:425: matched proposal id 1
ike V=root:0:ce13113404bcd448/0000000000000000:425: proposal id = 1:
ike V=root:0:ce13113404bcd448/0000000000000000:425:   protocol = IKEv2:
ike V=root:0:ce13113404bcd448/0000000000000000:425:      encapsulation = IKEv2/none
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=ENCR, val=AES_GCM_16 (key_len = 256)
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=INTEGR, val=NONE
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=PRF, val=PRF_HMAC_SHA2_512
ike V=root:0:ce13113404bcd448/0000000000000000:425:         type=DH_GROUP, val=MODP2048.
ike V=root:0:ce13113404bcd448/0000000000000000:425: lifetime=28800
ike V=root:0:ce13113404bcd448/0000000000000000:425: SA proposal chosen, matched gateway xxxx_yyyy
ike V=root:0:xxxx_yyyy:xxxx_yyyy: created connection: 0x9b88680 5 xx.xx.xx.xxx->yyy.yy.yy.yy:500.
ike V=root:0:xxxx_yyyy:425: processing notify type NAT_DETECTION_SOURCE_IP
ike V=root:0:xxxx_yyyy:425: processing NAT-D payload
ike V=root:0:xxxx_yyyy:425: NAT not detected
ike V=root:0:xxxx_yyyy:425: process NAT-D
ike V=root:0:xxxx_yyyy:425: processing notify type NAT_DETECTION_DESTINATION_IP
ike V=root:0:xxxx_yyyy:425: processing NAT-D payload
ike V=root:0:xxxx_yyyy:425: NAT not detected
ike V=root:0:xxxx_yyyy:425: process NAT-D
ike V=root:0:xxxx_yyyy:425: processing notify type FRAGMENTATION_SUPPORTED
ike V=root:0:xxxx_yyyy:425: processing notify type SIGNATURE_HASH_ALGORITHMS
ike V=root:0:xxxx_yyyy:425: responder preparing SA_INIT msg
ike V=root:0:xxxx_yyyy:425: create NAT-D hash local xx.xx.xx.xxx/500 remote yyy.yy.yy.yy/500
ike 0:xxxx_yyyy:425: out CE13113404BCD44892FD77E016634BD52120222000000000000001A02200002800000024010100030300000C01000014800E01000300000802000007000000080400000E28000108000E00006D680EFF097280F720E80B94384D0DAD9BCE81FAECA826147D580C0ED71E9E71EF879934144AE8A70341A84F44315FCD06226577A629DE0CD919EDAAA921DE7F28DDF04F54085E2E3E54569464189B9A83C3B44EFBD40E3FCDE4367D6D3C8590BB8A7BA35BDC6EA93DD53C0B3B8AD6681FC477656BAB46A1EB4C018BEE2ECCE8642FDD377599873E4D09ACF8DFE25D90F6A5BD40F750FB28B8898D25388AB6D1E0169E497858BC1A6B30610672DDDC3996DB7D4F10119D816B1BDA43B45480E74D25AA3B5333E4829CC4ED223198A162563A5BDBBFFC5C08B153DDDB85043B974C8139573C53020144793685B2096E1FA9A2323A84248EEC33395163C393CFBB29000014C5258202F40D0720062590DC2BF8A4BC2900001C000040047CDE7052253BE12E3E2569F9772D6A895AED1B112900001C00004005D42D8954D36B114D2FA36CCD0B73E3E999C454D6000000080000402E
ike V=root:0:xxxx_yyyy:425: sent IKE msg (SA_INIT_RESPONSE): xx.xx.xx.xxx:500->yyy.yy.yy.yy:500, len=416, vrf=0, id=ce13113404bcd448/92fd77e016634bd5, oif=5
ike 0:xxxx_yyyy:425: IKE SA ce13113404bcd448/92fd77e016634bd5 SK_ei 36:88A28258A68BA7DA1CD8085A9DE2A361E43DBE648A34B667181E580FFA20CED8401D5190
ike 0:xxxx_yyyy:425: IKE SA ce13113404bcd448/92fd77e016634bd5 SK_er 36:EFD1FC8AAB18D24C7CFA332B17C6BBE028FBD9BF68CF0FDC44842C7E82704F7136C1FF3E
ike V=root:0: comes yyy.yy.yy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=295....
ike V=root:0: IKEv2 exchange=AUTH id=ce13113404bcd448/92fd77e016634bd5:00000001 len=295
ike 0: in CE13113404BCD44892FD77E016634BD52E20230800000001000001272300010BE03AE2F6876ECBB0E4441605B3C94C11CFABFCFC853ABEFC27AD88DFB9A484100F94F783FA09C87E26C2623A35FEC01D1F6A2F30EDCCFEB85640B5BD1D7E67E1E02D04ADAB3849AA1F162A18E4A02C5B7E8E89ED994363B3314996384CB9D2F57315B1F8ADB936BDE688D0F542E3035D020C904C0D51AF35DF54E131F458105EB64C1B5615E0F2BE032265CC3BC29910321F6F5006E7C0C593C0B9CAFA298B522E5C4CF8C8380FF0D2DFFC8DF0740D569E053E3A9A1ADD35B6EDE12F7C48CE4EEB785CF26CDD7705FA5807D5178523B7D119165EC339D620D0EE5329CFBD43203C2B70B95989E4E3445D23480ACD8B1AF85823369FFEEB941712E3D2DCEDCC0599FD6F5955EF2B
ike 0:xxxx_yyyy:425: dec CE13113404BCD44892FD77E016634BD52E202308000000010000010E230000042900001C0200000063796265726D636D2E6475636B646E732E6F72672400000800004000270000160200000072656D6F74652E6B6F75702E61742900004802000000C4F6D080205DACBFFDB1933FFD07CE3AD5FE21177FA436EE2EC064DD66AC534E837E09376E4F19835379461CADDE0D81A8652F5B173C35E3357E17516436B950210000080000400A2C0000240000002001030402CE30389F0300000C01000014800E010000000008050000002D00001801000000070000100000FFFFC0A80A00C0A80AFF2900001801000000070000100000FFFFC0A8A900C0A8A9FF29000008000040210000000800004024
ike V=root:0:xxxx_yyyy:425: responder received AUTH msg
ike V=root:0:xxxx_yyyy:425: processing notify type INITIAL_CONTACT
ike V=root:0:xxxx_yyyy:425: processing notify type ESP_TFC_PADDING_NOT_SUPPORTED
ike V=root:0:xxxx_yyyy:425: processing notify type EAP_ONLY_AUTHENTICATION
ike V=root:0:xxxx_yyyy:425: processing notify type MESSAGE_ID_SYNC_SUPPORTED
ike V=root:0:xxxx_yyyy:425: received peer identifier FQDN 'yyyyyyyy.yyyyyy.yyy'
ike V=root:0:xxxx_yyyy:425: auth verify done
ike V=root:0:xxxx_yyyy:425: responder AUTH continuation
ike V=root:0:xxxx_yyyy:425: authentication succeeded
ike V=root:0:xxxx_yyyy:425: responder creating new child
ike V=root:0:xxxx_yyyy:425:19595: peer proposal:
ike V=root:0:xxxx_yyyy:425:19595: TSi_0 0:192.168.10.0-192.168.10.255:0
ike V=root:0:xxxx_yyyy:425:19595: TSr_0 0:192.168.169.0-192.168.169.255:0
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: comparing selectors
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: matched by rfc-rule-2
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: phase2 matched by subset
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: accepted proposal:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: TSi_0 0:192.168.10.0-192.168.10.255:0
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: TSr_0 0:192.168.169.0-192.168.169.255:0
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: autokey
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: incoming child SA proposal:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: proposal id = 1:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:   protocol = ESP:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:      encapsulation = TUNNEL
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         type=ENCR, val=AES_GCM_16 (key_len = 256)
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         type=ESN, val=NO
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         PFS is disabled
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: matched proposal id 1
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: proposal id = 1:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:   protocol = ESP:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:      encapsulation = TUNNEL
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         type=ENCR, val=AES_GCM_16 (key_len = 256)
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         type=INTEGR, val=AUTH_NONE
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         type=ESN, val=NO
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595:         PFS is disabled
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: lifetime=3600
ike V=root:0:xxxx_yyyy:425: responder preparing AUTH msg
ike V=root:0:xxxx_yyyy:425: established IKE SA ce13113404bcd448/92fd77e016634bd5
ike V=root:0:xxxx_yyyy:425: check peer route: if_addr4_rcvd=0, if_addr6_rcvd=0, mode_cfg=0
ike V=root:0:xxxx_yyyy:425: processing INITIAL-CONTACT
ike V=root:0:xxxx_yyyy: flushing
ike V=root:0:xxxx_yyyy: flushed
ike V=root:0:xxxx_yyyy:425: processed INITIAL-CONTACT
ike V=root:0:xxxx_yyyy: set oper up
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: set sa life soft seconds=3328.
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: set sa life hard seconds=3600.
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: IPsec SA selectors #src=1 #dst=1
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: src 0 7 0:192.168.169.0-192.168.169.255:0
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: dst 0 7 0:192.168.10.0-192.168.10.255:0
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: add IPsec SA: SPIs=e8e6a451/ce30389f
ike 0:xxxx_yyyy:425:xxxx_yyyy:19595: IPsec SA dec spi e8e6a451 key 36:F005C9651CF3BA3FE6672EF023B1FB9747CE5C1FF062DE7CEBDA6252331CC9C7A9B0AA34 auth 0:
ike 0:xxxx_yyyy:425:xxxx_yyyy:19595: IPsec SA enc spi ce30389f key 36:0A7D4B7CBFC8FCD38D09F9025A9A9147F3092562F16046AACA49704EBBD8F6ADDDDCC22F auth 0:
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: added IPsec SA: SPIs=e8e6a451/ce30389f
ike V=root:0:xxxx_yyyy:425:xxxx_yyyy:19595: sending SNMP tunnel UP trap
ike V=root:0:xxxx_yyyy: static tunnel up event 0.0.0.0 (dev=24)
ike V=root:0:xxxx_yyyy: static tunnel up event :: (dev=24)
ike 0:xxxx_yyyy:425: enc 270000160200000072656D6F74652E6B6F75702E617429000048020000009F292A1510A4E5BE9F8264B8CE6429A113748AE5B789EA884346DFD1278F2664D62C2AACE7C875C6DFDD477C1FC30D0F237C58F86F6C90059368D57053BEC30521000008000040242C0000240000002001030402E8E6A4510300000C01000014800E010000000008050000002D00001801000000070000100000FFFFC0A80A00C0A80AFF0000001801000000070000100000FFFFC0A8A900C0A8A9FF080706050403020108
ike 0:xxxx_yyyy:425: out CE13113404BCD44892FD77E016634BD52E20232000000001000000FB240000DF01ED8B0202DB9C1B82111CC473ED46F7AA8A15A2C7A8A246EA92BA2916CCBFA3FD67D6617FCC9C7F7EDA785BEC254901FAE52DE358AA360ED33010BE36A6297B387EE05DAB7F1C81DCDF268F08068D560BC8C2A40E644FFA3E11C0B6C341F827830C93951C85A73B1CC181A96628E5F9F0133E7574F2BA595E8E73FE8ECE22C3D0F81F77F524D7AAA99296775053B205B110B51F3EC4C2B81D6EF8D473EFBB07638C3F804AA3CD1100A89329FB2B71C5089325520F6667E1DAAE97014C2E3B487C55882C46BB2FAF0016A229FBCA36DB10E318BF67B58B53716FC8
ike V=root:0:xxxx_yyyy:425: sent IKE msg (AUTH_RESPONSE): xx.xx.xx.xxx:500->yyy.yy.yy.yy:500, len=251, vrf=0, id=ce13113404bcd448/92fd77e016634bd5:00000001, oif=5
ike :shrank heap by 114688 bytes
ike V=root:0: comes yyy.yyy.yyy.yy:500->xx.xx.xx.xxx:500,ifindex=5,vrf=0,len=65....
ike V=root:0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=8b79c9b890913093/b8eae4473c0f280c:00000560 len=65
ike 0: in 8B79C9B890913093B8EAE4473C0F280C2E202528000005600000004100000025117C81344801C6B83D7C60976852C4FB0DF6E6D09036A638137341D9EB8EF22737


I have a S2S IPSec tunnel between an Opnsense (24.7.11) and a Fortigate 60F (current FortiOS) device. Establishing a connection is working but after some time (Phase 2 rekeying?) the tunnel sometimes breaks and comes back way later without any action on both sides. I captured a log trace (no debug) on the OpnSense side, see below. Both configs are correct in my point of view.

I can probably catch the Fortigate log next time it happens.
Any ideas, is a debug log necessary and if yes, there are a lot of logging options with IPSec, which one?
I'm no VPN or network expert so please excuse if this is an easy mistake on my side.

Code Select Expand

2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> CHILD_SA closed   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> received DELETE for ESP CHILD_SA with SPI e8e6a428   
2024-12-28T22:13:46    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> parsed INFORMATIONAL response 3 [ D ]   
2024-12-28T22:13:46    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (77 bytes)   
2024-12-28T22:13:46    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (69 bytes)   
2024-12-28T22:13:46    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> generating INFORMATIONAL request 3 [ D ]   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending DELETE for ESP CHILD_SA with SPI c944a6f1   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> closing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{10} with SPIs c944a6f1_i (120834 bytes) e8e6a428_o (0 bytes) and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> outbound CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{11} established with SPIs cd6dbc5f_i e8e6a429_o and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> inbound CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{11} established with SPIs cd6dbc5f_i e8e6a429_o and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T22:13:46    3    Informational    charon    82877    14[CFG] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> selected proposal: ESP:AES_GCM_16_256/MODP_2048/NO_EXT_SEQ   
2024-12-28T22:13:46    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> parsed CREATE_CHILD_SA response 2 [ SA No KE TSi TSr ]   
2024-12-28T22:13:46    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (441 bytes)   
2024-12-28T22:13:46    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T22:13:46    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]   
2024-12-28T22:13:46    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> establishing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{11} reqid 1   
2024-12-28T22:13:46    3    Informational    charon    82877    14[KNL] creating rekey job for CHILD_SA ESP/0xc944a6f1/yyy.yy.yy.yy   
2024-12-28T21:18:56    20    Notice    charon    40648    [UPDOWN] received up-client event for reqid 1   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{10} established with SPIs c944a6f1_i e8e6a428_o and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T21:18:56    3    Informational    charon    82877    14[CFG] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> selected proposal: ESP:AES_GCM_16_256/NO_EXT_SEQ   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> maximum IKE_SA lifetime 29223s   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> scheduling rekeying in 26343s   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> IKE_SA a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5[3] established between yyy.yy.yy.yy[yyyyy.yyyyy.yyy]...xx.xx.xx.xxx[xxxxx.xxxx.xx]   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> authentication of 'xxxxx.xxxx.xx' with pre-shared key successful   
2024-12-28T21:18:56    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> parsed IKE_AUTH response 1 [ IDr AUTH N(MSG_ID_SYN_SUP) SA TSi TSr ]   
2024-12-28T21:18:56    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (251 bytes)   
2024-12-28T21:18:56    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (295 bytes)   
2024-12-28T21:18:56    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> generating IKE_AUTH request 1 [ IDi N(INIT_CONTACT) IDr AUTH N(ESP_TFC_PAD_N) SA TSi TSr N(EAP_ONLY) N(MSG_ID_SYN_SUP) ]   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> establishing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{10} reqid 1   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> authentication of 'yyyyy.yyyyy.yyy' (myself) with pre-shared key   
2024-12-28T21:18:56    3    Informational    charon    82877    14[CFG] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> selected proposal: IKE:AES_GCM_16_256/PRF_HMAC_SHA2_512/MODP_2048   
2024-12-28T21:18:56    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> parsed IKE_SA_INIT response 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) ]   
2024-12-28T21:18:56    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (416 bytes)   
2024-12-28T21:18:56    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (456 bytes)   
2024-12-28T21:18:56    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> retransmit 1 of request with message ID 0   
2024-12-28T21:18:52    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (456 bytes)   
2024-12-28T21:18:52    3    Informational    charon    82877    14[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> generating IKE_SA_INIT request 0 [ SA KE No N(NATD_S_IP) N(NATD_D_IP) N(FRAG_SUP) N(HASH_ALG) N(REDIR_SUP) ]   
2024-12-28T21:18:52    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|3> initiating IKE_SA a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5[3] to xx.xx.xx.xxx   
2024-12-28T21:18:52    3    Informational    charon    82877    09[KNL] creating acquire job for policy yyy.yy.yy.yy/32 === xx.xx.xx.xxx/32 with reqid {1}   
2024-12-28T21:18:50    3    Informational    charon    82877    14[KNL] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> unable to delete SAD entry with SPI cfcc902c: No such process (3)   
2024-12-28T21:18:50    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> giving up after 5 retransmits   
2024-12-28T21:17:34    3    Informational    charon    82877    14[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:17:34    3    Informational    charon    82877    14[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> retransmit 5 of request with message ID 4   
2024-12-28T21:17:08    3    Informational    charon    82877    10[KNL] creating rekey job for CHILD_SA ESP/0xc18c99e0/yyy.yy.yy.yy   
2024-12-28T21:16:52    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:16:52    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> retransmit 4 of request with message ID 4   
2024-12-28T21:16:29    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:16:29    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> retransmit 3 of request with message ID 4   
2024-12-28T21:16:16    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:16:16    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> retransmit 2 of request with message ID 4   
2024-12-28T21:16:09    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:16:09    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> retransmit 1 of request with message ID 4   
2024-12-28T21:16:05    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T21:16:05    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> generating CREATE_CHILD_SA request 4 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]   
2024-12-28T21:16:05    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> establishing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{9} reqid 1   
2024-12-28T21:16:05    3    Informational    charon    82877    10[KNL] creating rekey job for CHILD_SA ESP/0xe8e6a426/xx.xx.xx.xxx   
2024-12-28T20:17:59    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (69 bytes)   
2024-12-28T20:17:59    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> generating CREATE_CHILD_SA response 0 [ N(NO_CHILD_SA) ]   
2024-12-28T20:17:59    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> unable to rekey, ESP CHILD_SA with SPI e8e6a424 not found   
2024-12-28T20:17:59    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> parsed CREATE_CHILD_SA request 0 [ N(REKEY_SA) SA No KE TSi TSr ]   
2024-12-28T20:17:59    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (453 bytes)   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> CHILD_SA closed   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> received DELETE for ESP CHILD_SA with SPI e8e6a424   
2024-12-28T20:17:54    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> parsed INFORMATIONAL response 3 [ D ]   
2024-12-28T20:17:54    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (77 bytes)   
2024-12-28T20:17:54    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (69 bytes)   
2024-12-28T20:17:54    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> generating INFORMATIONAL request 3 [ D ]   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending DELETE for ESP CHILD_SA with SPI c2e49130   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> closing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{7} with SPIs c2e49130_i (120860 bytes) e8e6a424_o (0 bytes) and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> outbound CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{8} established with SPIs c18c99e0_i e8e6a426_o and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> inbound CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{8} established with SPIs c18c99e0_i e8e6a426_o and TS 192.168.10.0/24 === 192.168.169.0/24   
2024-12-28T20:17:54    3    Informational    charon    82877    10[CFG] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> selected proposal: ESP:AES_GCM_16_256/MODP_2048/NO_EXT_SEQ   
2024-12-28T20:17:54    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> parsed CREATE_CHILD_SA response 2 [ SA No KE TSi TSr ]   
2024-12-28T20:17:54    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> received packet: from xx.xx.xx.xxx[500] to yyy.yy.yy.yy[500] (441 bytes)   
2024-12-28T20:17:54    3    Informational    charon    82877    10[NET] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> sending packet: from yyy.yy.yy.yy[500] to xx.xx.xx.xxx[500] (469 bytes)   
2024-12-28T20:17:54    3    Informational    charon    82877    10[ENC] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> generating CREATE_CHILD_SA request 2 [ N(REKEY_SA) N(ESP_TFC_PAD_N) SA No KE TSi TSr ]   
2024-12-28T20:17:54    3    Informational    charon    82877    10[IKE] <a075e27f-ad8d-4e7a-bd35-2f5c5ea0cee5|2> establishing CHILD_SA 38ecc2d4-7b62-4bae-a3a1-58ac8e93bc9f{8} reqid 1   
2024-12-28T20:17:54    3    Informational    charon    82877    05[KNL] creating rekey job for CHILD_SA ESP/0xc2e49130/yyy.yy.yy.yy


@bunchofreeds:
Very interesting article, thank you!
I finally gave up and switched my hardware, I was never able to get my full speed, although some entries in some forums suggest that it was possible with older BSD versions. There are also articles that suggest that with the same hardware it is no problem to get full speed with Linux (OpenWRT), I never tested this myself.

Just one try to bump this up, maybe someone can help?
If not, any recommendations for a new hardware for my setup (should be affordable), like J4125 devices maybe?

I recently got FTTH (yeah) with 250 MBit download speed.
Normal Setup: OTN -> provider modem (which provides the login) -> Opnsense (APU3 board, DHCP)
With this setup I get full speed > 250-260 MBit

There is a way to get rid of the provider modem, so my setup will look like: OTN -> OpnSense

Problem: OpnSense has to dial in with PPPoE.
I read a few articles and OpnSense seems to have troubles with PPPoE in terms of speed (tests with APU3 and OpenWRT -> full speed up to 900 MBit).
I currently manage to get about 220 MBit. A future upgrade to 1 GBit Internet speed would be useless.

I read about tuning settings, but at least some of these settings are not applicable with 23.1.
Are there any useful settings to increase speed?