Constant on negotiate on IPsec phase 2

[YL]

Hello, my friend. 

We did the site to side between FG-100D(6.2.9) and FG-60F(6.2.9).

The tunnel is up right now, but found lots of record about IPsec SA negotiate Events on 100D.

I have disable the npu-offload on 60F, but the issues still happen, is there any other way we can do on it?

Any help and advice would be much appreciated.

VPN EVENT:

 dadate=2022-09-29 time=09:31:40 logid="0101037135" type="event" subtype="vpn" level="notice" vd="VDOM-Colo" eventtime=1664415100710345489 tz="+0800" logdesc="IPsec phase 2 SA deleted" msg="delete IPsec phase 2 SA" action="delete_ipsec_sa" remip=172.31.xx.xx locip=172.31.xx.xx remport=500 locport=500 outintf="port1" cookies="6a8ebfd24352f97c/a789ee80bedabfad" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="to-XXXXXXX" in_spi="14f35b6d" out_spi="ca30663d"

date=2022-09-29 time=09:31:37 logid="0101037122" type="event" subtype="vpn" level="notice" vd="VDOM-Colo" eventtime=1664415097318333745 tz="+0800" logdesc="Negotiate IPsec phase 2" msg="negotiate IPsec phase 2" action="negotiate" remip=172.31.xx.xx locip=172.31.xx.xx remport=500 locport=500 outintf="port1" cookies="6a8ebfd24352f97c/a789ee80bedabfad" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="to-XXXXXXX" status="success" role="responder" esptransform="ESP_AES" espauth="HMAC_SHA1"

date=2022-09-29 time=09:31:37 logid="0101037129" type="event" subtype="vpn" level="notice" vd="VDOM-Colo" eventtime=1664415097318276635 tz="+0800" logdesc="Progress IPsec phase 2" msg="progress IPsec phase 2" action="negotiate" remip=172.31.xx.xx locip=172.31.xx.xx remport=500 locport=500 outintf="port1" cookies="6a8ebfd24352f97c/a789ee80bedabfad" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="to-XXXXXXX" status="success" init="remote" mode="quick" dir="inbound" stage=2 role="responder" result="DONE"
date=2022-09-29 time=09:31:37 logid="0101037129" type="event" subtype="vpn" level="notice" vd="VDOM-Colo" eventtime=1664415097301668202 tz="+0800" logdesc="Progress IPsec phase 2" msg="progress IPsec phase 2" action="negotiate" remip=172.31.xx.xx locip=172.31.xx.xx remport=500 locport=500 outintf="port1" cookies="6a8ebfd24352f97c/a789ee80bedabfad" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="to-XXXXXXX" status="success" init="remote" mode="quick" dir="outbound" stage=1 role="responder" result="OK"

date=2022-09-29 time=09:31:37 logid="0101037133" type="event" subtype="vpn" level="notice" vd="VDOM-Colo" eventtime=1664415097301452095 tz="+0800" logdesc="IPsec SA installed" msg="install IPsec SA" action="install_sa" remip=172.31.xx.xx locip=172.31.xx.xx remport=500 locport=500 outintf="port1" cookies="6a8ebfd24352f97c/a789ee80bedabfad" user="N/A" group="N/A" useralt="N/A" xauthuser="N/A" xauthgroup="N/A" assignip=N/A vpntunnel="to-XXXXXXX" role="responder" in_spi="ca30663f" out_spi="14f35b6f"

debug mode output as below:

ike 0: comes 172.31.xx.xx:500->172.31.xx.xx:500,ifindex=8....
ike 0: IKEv1 exchange=Quick id=fe1432b2b2a86cd1/67e6f70300c4d3fc:1e05a8f1 len=204
ike 0: in FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F1000000CC731D5F549877B1871D7DFA39DA5DA7D85DB879F3148E8BAE8382EF6F1893304A420129AEFF90003FBA8F80CC80E572E120F16936F7BB58C045A7C43CF052077DADFD5EE0B39528F51882AA847F7999F7A94EFC081C4FE3A520EF9CFFBCC37EABCBC6F442AC059FE2A8450D2344B7EF5AB29B3E04047D3E8789F0BCBD02B3CA5049F1A87E9A1690534CBDFE25073FC5CCAB7A1F06C728E26EE9C799CC1A684E2E3E6BDEAAA7C83577DFFF9898B43A3095
ike 0:to-C:107847:9661355: responder received first quick-mode message
ike 0:to-C:107847: dec FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F1000000CC010000188D34649CAA00A38BC0D8086667D85C68CF42ADED0A00006000000001000000010000005401030402CA30701403000024010C0000800100018002A8C0800100028002140080040001800600808005000200000024020C0000800100018002A8C0800100028002140080040001800601008005000205000014AE70056AEF72CD0BC9813B047B629FB2050000100400000000000000000000000000001004000000000000000000000068D6C103
ike 0:to-C:107847:9661355: peer proposal is: peer:0:0.0.0.0-255.255.255.255:0, me:0:0.0.0.0-255.255.255.255:0
ike 0:to-C:107847:to-C:9661355: trying
ike 0:to-C:107847:to-C:9661355: matched phase2
ike 0:to-C:107847:to-C:9661355: autokey
ike 0:to-C:107847:to-C:9661355: my proposal:
ike 0:to-C:107847:to-C:9661355: proposal id = 1:
ike 0:to-C:107847:to-C:9661355: protocol id = IPSEC_ESP:
ike 0:to-C:107847:to-C:9661355: trans_id = ESP_AES_CBC (key_len = 128)
ike 0:to-C:107847:to-C:9661355: encapsulation = ENCAPSULATION_MODE_TUNNEL
ike 0:to-C:107847:to-C:9661355: type = AUTH_ALG, val=SHA1
ike 0:to-C:107847:to-C:9661355: trans_id = ESP_AES_CBC (key_len = 256)
ike 0:to-C:107847:to-C:9661355: encapsulation = ENCAPSULATION_MODE_TUNNEL
ike 0:to-C:107847:to-C:9661355: type = AUTH_ALG, val=SHA1
ike 0:to-C:107847:to-C:9661355: incoming proposal:
ike 0:to-C:107847:to-C:9661355: proposal id = 1:
ike 0:to-C:107847:to-C:9661355: protocol id = IPSEC_ESP:
ike 0:to-C:107847:to-C:9661355: trans_id = ESP_AES_CBC (key_len = 128)
ike 0:to-C:107847:to-C:9661355: encapsulation = ENCAPSULATION_MODE_TUNNEL
ike 0:to-C:107847:to-C:9661355: type = AUTH_ALG, val=SHA1
ike 0:to-C:107847:to-C:9661355: trans_id = ESP_AES_CBC (key_len = 256)
ike 0:to-C:107847:to-C:9661355: encapsulation = ENCAPSULATION_MODE_TUNNEL
ike 0:to-C:107847:to-C:9661355: type = AUTH_ALG, val=SHA1
ike 0:to-C:107847:to-C:9661355: negotiation result
ike 0:to-C:107847:to-C:9661355: proposal id = 1:
ike 0:to-C:107847:to-C:9661355: protocol id = IPSEC_ESP:
ike 0:to-C:107847:to-C:9661355: trans_id = ESP_AES_CBC (key_len = 128)
ike 0:to-C:107847:to-C:9661355: encapsulation = ENCAPSULATION_MODE_TUNNEL
ike 0:to-C:107847:to-C:9661355: type = AUTH_ALG, val=SHA1
ike 0:to-C:107847:to-C:9661355: using tunnel mode.
ike 0:to-C: schedule auto-negotiate
ike 0:to-C:107847:to-C:9661355: SA life soft seconds=42932.
ike 0:to-C:107847:to-C:9661355: SA life hard seconds=43200.
ike 0:to-C:107847:to-C:9661355: set sa life soft/hard kbytes=2560/5120.
ike 0:to-C:107847:to-C:9661355: IPsec SA selectors #src=1 #dst=1
ike 0:to-C:107847:to-C:9661355: src 0 4 0:0.0.0.0/0.0.0.0:0
ike 0:to-C:107847:to-C:9661355: dst 0 4 0:0.0.0.0/0.0.0.0:0
ike 0:to-C:107847:to-C:9661355: add IPsec SA: SPIs=14f3654c/ca307014
ike 0:to-C:107847:to-C:9661355: IPsec SA dec spi 14f3654c key 16:F5F32FA0466A8ACE2D2D8FA0B7397618 auth 20:7187488E5494ACB49DB54000EEEBBA7D338DE035
ike 0:to-C:107847:to-C:9661355: IPsec SA enc spi ca307014 key 16:38FDB3C433FFD65ABBAB8D18C535E3F4 auth 20:D9341D44F167B5E514F74C8E9C1306E89C096012
ike 0:to-C:107847:to-C:9661355: added IPsec SA: SPIs=14f3654c/ca307014
ike 0:to-C:107847: enc FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F1000000A401000018DEF7BB6A3E8CE4D5250E0F55A111721E848714410A00003C0000000100000001000000300103040114F3654C00000024010C0000800100018002A8C08001000280021400800400018006008080050002050000149B6E2CC4CBE7C3849305EFC5905E3AE30500001004000000000000000000000000000010040000000000000000000000
ike 0:to-C:107847: out FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F1000000AC289AE21E424BFD400F8D6E315A878BB003944E921AE5241483894EEB7BBA67E7B361EA2DFE073A4513060B4D7ED78363B54228486E75965EEB58FE3E7E0BA540463CD359194FEED20BEB7F981AD31ECC6F7906A73C86E4B374E772524EBFB6DEDE7BF6FF2E57D413BAE59C46B576D6B2F0CE9AB76FC5E93799EBAB7C2356C799086D935CCADEA12FDE5D8A7713543A0D
ike 0:to-C:107847: sent IKE msg (quick_r1send): 172.31.xx.xx:500->172.31.xx.xx:500, len=172, id=fe1432b2b2a86cd1/67e6f70300c4d3fc:1e05a8f1
ike 0:to-C: IPsec SA ca307010/14f36548 hard expired 8 172.31.xx.xx->172.31.xx.xx:0 SA count 3 of 3
ike 0:to-C:107847: send IPsec SA delete, spi 14f36548
ike 0:to-C:107847: enc FE1432B2B2A86CD167E6F70300C4D3FC081005016538961C000000440C0000182C88CA9B20C3CDAA925A6FCDEA8806FFD12C674E00000010000000010304000114F36548
ike 0:to-C:107847: out FE1432B2B2A86CD167E6F70300C4D3FC081005016538961C0000004C51123F4AE54EBC2C1CDA0F87523B244F7EB6711142FDA0F3D24E2582F7CAA6FB230EFA8BD2BDD742718507EDF985C59F
ike 0:to-C:107847: sent IKE msg (IPsec SA_DELETE-NOTIFY): 172.31.xx.xx:500->172.31.xx.xx:500, len=76, id=fe1432b2b2a86cd1/67e6f70300c4d3fc:6538961c
ike 0: comes 172.31.xx.xx:500->172.31.xx.xx:500,ifindex=8....
ike 0: IKEv1 exchange=Quick id=fe1432b2b2a86cd1/67e6f70300c4d3fc:1e05a8f1 len=60
ike 0: in FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F10000003CA99B3F7E4D991D6A8831E47D75DD583CD874DC3C38E648BF11F5125CA07B242D
ike 0:to-C:107847: dec FE1432B2B2A86CD167E6F70300C4D3FC081020011E05A8F10000003C00000018FE729A35FB384738EA7768D531649028822D2BE9918BCFDFCD371A07
ike 0:to-C:to-C:9661355: send SA_DONE SPI 0xca307014

[pminarik · Accepted solution]

The debugs don't really seem all that interesting, I'm afraid.

They show a regular three-way Quick Mode negotiation for SA 14f3654c/ca307014, and in the middle there is an informational message informing to delete SA 14f36548, after it expired due to reaching it's time-based lifetime.

If this repeats, I would suggest checking the debugs of the side initiating these phase2 (re)negotiations. These debugs show that the other side initiated the phase2 negotiation, so if this is a consistent pattern, check the debugs on the other device.

You could also open a support ticket with TAC for this.