Hello,
I am not an expert on IPSec and its terminology, so I apologize if I write something inaccurate, but I try to do my best. I have an IPSec s2s tunnel between Palo Alto PA-220 and Mikrotik RB4011. The RB4011 is behind NAT so it initiates the connection, Palo has a public IP. The tunnel works, but from time to time the rekey of IPSec keys procedure fails. On both devices, the IPSec keys lifetime is configured to one hour. The whole rekey process is going well until Palo removes the old keys. Firstly Palo sends delete message to the Mikrotik, then Palo deletes the keys and sometimes after removing the keys Palo receives delete message from the Mikrotik. When the delete message arrives, Palo no longer has the old keys and they cannot find them. This will cause that Palo aborts the whole connection and negotiates it again. This, of course, causes outages for several minutes. The failure is visible in the following part of ikemgr.log ("x.x.x.x" is the public IP of Palo, "y.y.y.y" is the public IP of Mikrotik).
2020-12-02 00:42:58.029 +0100 [PNTF]: { 3: }: ====> IKEv2 CHILD SA NEGOTIATION STARTED AS RESPONDER, rekey; gateway peer-france-vl <====
====> Initiated SA: x.x.x.x[4500]-y.y.y.y[4500] message id:0x00000005 parent SN:459 <====
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: TS matching for configured selector tunnel-france-vl:france-vl-to-czechia-brno 10.0.0.0[0]/11-10.32.0.0[0]/19 proto 0
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: .. check local TS (num 1, TS0 is not specific) against selector 0:10.0.0.0[0]/11
2020-12-02 00:42:58.029 +0100 [DEBG]: { : 16}: ... TS 0: exact match
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: ... result: local TS = 10.0.0.0[0]/11
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: .. check remote TS (num 1, TS0 is not specific) against selector 0:10.32.0.0[0]/19
2020-12-02 00:42:58.029 +0100 [DEBG]: { : 16}: ... TS 0: exact match
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: ... result: remote TS = 10.32.0.0[0]/19
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: TS matching result: TS_l match(=), TS_r match(=) *
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: selector chosen tunnel-france-vl:france-vl-to-czechia-brno: tid 16
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: success
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: see whether there's matching transform
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: found same ID. compare attributes
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: OK; advance to next of my transform type
2020-12-02 00:42:58.029 +0100 [DEBG]: { 3: 16}: success
2020-12-02 00:42:58.042 +0100 [INFO]: { 3: 16}: SADB_UPDATE proto=255 0.0.0.0[4500]=>x.x.x.x[4500] ESP tunl spi 0x83E9F5D3 auth=NON-AUTH enc=AES256-GCM16/36 lifetime soft 2926/0 hard 3600/0
2020-12-02 00:42:58.042 +0100 [INFO]: { 3: 16}: SADB_ADD proto=255 x.x.x.x[4500]=>y.y.y.y[4500] ESP tunl spi 0x0C47A617 auth=NON-AUTH enc=AES256-GCM16/36 lifetime soft 3114/0 hard 3600/0
2020-12-02 00:42:58.042 +0100 [DEBG]: { 3: 16}: sadb ts: port 0:65535 IP 10.0.0.0->10.31.255.255 proto:0 len:16
2020-12-02 00:42:58.042 +0100 [DEBG]: { 3: 16}: sadb ts: port 0:65535 IP 10.32.0.0->10.32.31.255 proto:0 len:16
2020-12-02 00:42:58.043 +0100 [PNTF]: { 3: 16}: ====> IPSEC KEY INSTALLATION SUCCEEDED; tunnel tunnel-france-vl:france-vl-to-czechia-brno <====
====> Installed SA: x.x.x.x[4500]-y.y.y.y[4500] SPI:0x83E9F5D3/0x0C47A617 lifetime 3600 Sec lifesize unlimited <====
2020-12-02 00:42:58.043 +0100 [PNTF]: { 3: 16}: ====> IKEv2 CHILD SA NEGOTIATION SUCCEEDED AS RESPONDER, rekey; tunnel tunnel-france-vl:france-vl-to-czechia-brno <====
====> Established SA: x.x.x.x[4500]-y.y.y.y[4500] message id:0x00000005, SPI:0x83E9F5D3/0x0C47A617 parent SN:459 <====
2020-12-02 00:42:58.044 +0100 [DEBG]: x.x.x.x[4500] - y.y.y.y[4500]:(nil) 1 times of 308 bytes message will be sent over socket 1025
2020-12-02 00:42:58.045 +0100 [INFO]: { 3: 16}: SPI 83E9F5D3 inserted by IPSec responder, return 0 0.
2020-12-02 00:42:58.046 +0100 [INFO]: { 3: }: KA found: x.x.x.x[4500]->y.y.y.y[4500] (in_use=2)
2020-12-02 00:42:58.048 +0100 [INFO]: { 3: 16}: SPI C0BC9062 removed by keymodify, return 0 0.
2020-12-02 00:42:58.048 +0100 [PNTF]: { 3: 16}: ====> IKEv2 CHILD SA DELETED AS RESPONDER, rekey; tunnel tunnel-france-vl:france-vl-to-czechia-brno <====
====> Deleted SA: x.x.x.x[4500]-y.y.y.y[4500] message id:0x00000004, SPI:0xC0BC9062/0x0B6DF5A6 parent SN:459 <====
2020-12-02 00:42:58.048 +0100 [INFO]: { 3: }: ikev2_request_initiator_start: SA state ESTABLISHED type 3 caller ikev2_child_delete
2020-12-02 00:42:58.048 +0100 [INFO]: { 3: }: IKEv2 INFO transmit: gateway peer-france-vl, message_id: 0x0000090B, type 3 SA state ESTABLISHED
2020-12-02 00:42:58.048 +0100 debug: sysd_queue_wr_event_add(sysd_queue.c:915): QUEUE: queue write event already added
2020-12-02 00:42:58.048 +0100 [DEBG]: x.x.x.x[4500] - y.y.y.y[4500]:(nil) 1 times of 100 bytes message will be sent over socket 1025
2020-12-02 00:42:58.049 +0100 [PNTF]: { 3: 16}: ====> IPSEC KEY DELETED; tunnel tunnel-france-vl:france-vl-to-czechia-brno <====
====> Deleted SA: x.x.x.x[4500]-y.y.y.y[4500] SPI:0xC0BC9062/0x0B6DF5A6 <====
2020-12-02 00:42:58.049 +0100 [INFO]: { 3: 16}: SADB_DELETE proto=255 src=0.0.0.0[0] dst=x.x.x.x[0] ESP spi=0xC0BC9062
2020-12-02 00:42:58.049 +0100 [INFO]: { 3: }: KA remove: x.x.x.x[4500]->y.y.y.y[4500]
2020-12-02 00:42:58.049 +0100 [DEBG]: { 3: }: KA tree dump: x.x.x.x[4500]->y.y.y.y[4500] (in_use=2)
2020-12-02 00:42:58.091 +0100 [DEBG]: processing isakmp packet
2020-12-02 00:42:58.091 +0100 [DEBG]: ===
2020-12-02 00:42:58.091 +0100 [DEBG]: 96 bytes message received from y.y.y.y
2020-12-02 00:42:58.091 +0100 [DEBG]: { 3: }: request exch type 37
2020-12-02 00:42:58.091 +0100 [DEBG]: { 3: }: update request message_id 0x6
2020-12-02 00:42:58.092 +0100 [INFO]: { 3: }: received DELETE payload, protocol ESP, num of SPI: 1 IKE SA state ESTABLISHED
2020-12-02 00:42:58.092 +0100 [INFO]: { 3: }: delete proto ESP spi 0x0B6DF5A6
2020-12-02 00:42:58.092 +0100 [PWRN]: { 3: }: can't find sa for proto ESP spi 0x0B6DF5A6
2020-12-02 00:42:58.092 +0100 [DEBG]: x.x.x.x[4500] - y.y.y.y[4500]:(nil) 1 times of 100 bytes message will be sent over socket 1025
2020-12-02 00:42:58.093 +0100 [DEBG]: processing isakmp packet
2020-12-02 00:42:58.093 +0100 [DEBG]: ===
2020-12-02 00:42:58.093 +0100 [DEBG]: 288 bytes message received from y.y.y.y
2020-12-02 00:42:58.093 +0100 [DEBG]: { 3: }: response exch type 37
2020-12-02 00:42:58.093 +0100 [DEBG]: { 3: }: update response message_id 0x90b
2020-12-02 00:42:58.093 +0100 [PERR]: { 3: }: received Notify payload protocol 0 type 43
2020-12-02 00:42:58.093 +0100 [INFO]: { 3: }: x.x.x.x[4500] - y.y.y.y[4500]:(nil) closing IKEv2 SA peer-france-vl:459, code 18
2020-12-02 00:42:58.093 +0100 [PNTF]: { 3: }: ====> IKEv2 IKE SA NEGOTIATION FAILED AS RESPONDER, non-rekey; gateway peer-france-vl <====
====> Failed SA: x.x.x.x[4500]-y.y.y.y[4500] SPI:c377b3486ea76198:3be1f1ebd76122a1 SN 459 <====
2020-12-02 00:42:58.093 +0100 [DEBG]: { 3: }: SA dying from state ESTABLISHED, caller ikev2_abort
2020-12-02 00:42:58.093 +0100 [DEBG]: { 3: }: keeping retransmit while state changed to DYING, CID 288787, child 0xffe800d700
2020-12-02 00:42:58.093 +0100 [PNTF]: { 3: 16}: ====> IPSEC KEY DELETED; tunnel tunnel-france-vl:france-vl-to-czechia-brno <====
====> Deleted SA: x.x.x.x[4500]-y.y.y.y[4500] SPI:0x83E9F5D3/0x0C47A617 <====
2020-12-02 00:42:58.095 +0100 [INFO]: { 3: 16}: SADB_DELETE proto=255 src=0.0.0.0[0] dst=x.x.x.x[0] ESP spi=0x83E9F5D3
2020-12-02 00:42:58.095 +0100 [DEBG]: { 3: }: SA deleted: state DYING, caller ikev2_abort
2020-12-02 00:42:58.095 +0100 [DEBG]: { 3: }: stop retransmit for sa 0xffe800d700 (DEAD), CID 288787, child 0xffe800d700
2020-12-02 00:42:58.098 +0100 [INFO]: { 3: 16}: SPI 83E9F5D3 removed by IKE abort, return 0 0.
2020-12-02 00:42:58.098 +0100 [INFO]: { 3: }: KA remove: x.x.x.x[4500]->y.y.y.y[4500]
2020-12-02 00:42:58.098 +0100 [DEBG]: { 3: }: KA tree dump: x.x.x.x[4500]->y.y.y.y[4500] (in_use=1)
2020-12-02 00:42:58.098 +0100 [DEBG]: { 3: }: KA removing this one...
2020-12-02 00:42:58.877 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:42:58.877 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:08.205 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:08.205 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:13.723 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:13.723 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:21.163 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:21.163 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:29.099 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:29.099 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:43.947 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:43.947 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:50.036 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:50.036 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:43:56.980 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:43:56.980 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:04.190 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:04.191 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:09.931 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:09.931 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:17.194 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:17.195 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:24.671 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:24.671 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:24.671 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:24.671 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:29.921 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:29.921 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:36.215 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:36.215 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:44.363 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:44.363 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:49.992 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:49.992 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:56.233 +0100 [DEBG]: { : 16}: keyacquire received: x.x.x.x[0] => 0.0.0.0[0]
2020-12-02 00:44:56.233 +0100 [DEBG]: { 3: }: initiate negotiation to dynamic peer from IKE gateway peer-france-vl is not allowed.
2020-12-02 00:44:58.135 +0100 [DEBG]: processing isakmp packetAs you can see on the following Smokeping graphs (I ping the Mikrotik inside the tunnel from a server behind Palo), outages are random and can occur several times a day.
