URGENT!! - IPSec problem

[darrencarr]

Hi All, I have an urgent problem that I need assistance with. I have two IPSec tunnels between my two sites. In both firewalls the tunnels are showing as up on both sides. No traffic is however passing over the links. When I debug the link I get the following ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785dfd7 seq 00000090 17 10.1.1.1->10.1.1.2:500 I get this for both links. Both have been working fine until this evening when I received an error 37916, since then I have not been able to send traffic between the two sites. I am using Forti OS 4.0 MR1, am using route based VPN. Any ideas? Thanks, Darren

[darrencarr]

This is more of the log taken from debug app ike -1 ike 0: unknown SPI a785e03c 16 10.1.2.2:500->10.1.2.1 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: send INVALID-SPI a785e03c ike 0:DR_Uecomm:4506: initiator creating new child request ike 0:DR_Uecomm:89214: sending NOTIFY msg ike 0:DR_Uecomm:4506:89214: send informational ike 0:DR_Uecomm:4506: send INFORMATIONAL ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL): 10.1.2.1:500->10.1.2.2:500, len=68 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL id=18c352027710aa5f/793ce8c0694bdaf7:00000261 len=68 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received informational request ike 0:DR_Uecomm:4506: processing delete request (proto 3) ike 0:DR_Uecomm: deleting IPsec SA with SPI c1e6fc10 ike 0:DR_Uecomm:4506: sending delete ack ike 0:DR_Uecomm:4506: send INFORMATIONAL_RESPONSE ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.2.1:500->10.1.2.2:500, len=68 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=18c352027710aa5f/793ce8c0694bdaf7:00000204 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received informational response ike 0:DR_Uecomm:89214: received NOTIFY acknowledgement ike 0:DR_Uecomm:4506:89214: processing informational acknowledgement ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL id=6f5926dd59973611/fffd5a84c726669c:000001a3 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: received informational request ike 0:DR_Optus:4505: send INFORMATIONAL_RESPONSE ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0:DR_Optus: link is idle 17 10.1.1.1->10.1.1.2:500 dpd=1 seqno=1244 ike 0:DR_Optus:4505: send IKEv2 DPD probe ike 0:DR_Optus:4505: initiator creating new child request ike 0:DR_Optus:89215: sending NOTIFY msg ike 0:DR_Optus:4505:89215: send informational ike 0:DR_Optus:4505: send INFORMATIONAL ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=6f5926dd59973611/fffd5a84c726669c:000001a7 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: clear pending DPD seqno=4676 ike 0:DR_Optus:4505: received informational response ike 0:DR_Optus:89215: received NOTIFY acknowledgement ike 0:DR_Optus:4505:89215: processing informational acknowledgement ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785e02c seq 000000cf 17 10.1.1.1->10.1.1.2:500 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL id=18c352027710aa5f/793ce8c0694bdaf7:00000262 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received informational request ike 0:DR_Uecomm:4506: send INFORMATIONAL_RESPONSE ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0:DR_Uecomm: link is idle 16 10.1.2.1->10.1.2.2:500 dpd=1 seqno=9df5 ike 0:DR_Uecomm:4506: send IKEv2 DPD probe ike 0:DR_Uecomm:4506: initiator creating new child request ike 0:DR_Uecomm:89216: sending NOTIFY msg ike 0:DR_Uecomm:4506:89216: send informational ike 0:DR_Uecomm:4506: send INFORMATIONAL ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=18c352027710aa5f/793ce8c0694bdaf7:00000205 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: clear pending DPD seqno=40437 ike 0:DR_Uecomm:4506: received informational response ike 0:DR_Uecomm:89216: received NOTIFY acknowledgement ike 0:DR_Uecomm:4506:89216: processing informational acknowledgement ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=CREATE_CHILD id=18c352027710aa5f/793ce8c0694bdaf7:00000263 len=420 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received create-child request ike 0:DR_Uecomm:4506: responder received CREATE_CHILD exchange ike 0:DR_Uecomm:4506: responder creating new child ike 0:DR_Uecomm:4506:89217: peer proposal is: peer:0.0.0.0-255.255.255.255, me:0.0.0.0-255.255.255.255, ports=0/0, protocol=0/0 ike 0:DR_Uecomm:4506:89217: trying DR_Uecomm_P2 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: matched phase2 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: autokey ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: incoming proposal: ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: proposal id = 1: ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: protocol = ESP: ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: encapsulation = TUNNEL ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: type=ENCR, val=3DES_CBC ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: type=INTEGR, val=SHA ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: type=DH_GROUP, val=1536 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: matched proposal id 1 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: PFS enabled, group=5 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: set sa life soft seconds=1748. ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: set sa life hard seconds=1800. ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: IPsec SA selectors #src=1 #dst=1 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: src 0 7 0.0.0.0-255.255.255.255 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: dst 0 7 0.0.0.0-255.255.255.255 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: add IPsec SA: SPIs=a785e03d/c1e6fc11 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: failed to add SA, error 22: Invalid argument ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: responder preparing CREATE_CHILD message ike 0:DR_Uecomm:4506: send CREATE_CHILD_RESPONSE ike 0:DR_Uecomm:4506: sent IKE msg (CREATE_CHILD_RESPONSE): 10.1.2.1:500->10.1.2.2:500, len=372 ike 0: unknown SPI a785e03d 16 10.1.2.2:500->10.1.2.1 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: ignoring invalid SPI a785e03d, IPsec SA just negotiated ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785e02c seq 000000d2 17 10.1.1.1->10.1.1.2:500 ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL id=6f5926dd59973611/fffd5a84c726669c:000001a4 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: received informational request ike 0:DR_Optus:4505: send INFORMATIONAL_RESPONSE ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0:DR_Optus: link is idle 17 10.1.1.1->10.1.1.2:500 dpd=1 seqno=1245 ike 0:DR_Optus:4505: send IKEv2 DPD probe ike 0:DR_Optus:4505: initiator creating new child request ike 0:DR_Optus:89218: sending NOTIFY msg ike 0:DR_Optus:4505:89218: send informational ike 0:DR_Optus:4505: send INFORMATIONAL ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=6f5926dd59973611/fffd5a84c726669c:000001a8 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: clear pending DPD seqno=4677 ike 0:DR_Optus:4505: received informational response ike 0:DR_Optus:89218: received NOTIFY acknowledgement ike 0:DR_Optus:4505:89218: processing informational acknowledgement ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL id=18c352027710aa5f/793ce8c0694bdaf7:00000264 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received informational request ike 0:DR_Uecomm:4506: send INFORMATIONAL_RESPONSE ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0:DR_Uecomm: link is idle 16 10.1.2.1->10.1.2.2:500 dpd=1 seqno=9df6 ike 0:DR_Uecomm:4506: send IKEv2 DPD probe ike 0:DR_Uecomm:4506: initiator creating new child request ike 0:DR_Uecomm:89219: sending NOTIFY msg ike 0:DR_Uecomm:4506:89219: send informational ike 0:DR_Uecomm:4506: send INFORMATIONAL ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=18c352027710aa5f/793ce8c0694bdaf7:00000206 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: clear pending DPD seqno=40438 ike 0:DR_Uecomm:4506: received informational response ike 0:DR_Uecomm:89219: received NOTIFY acknowledgement ike 0:DR_Uecomm:4506:89219: processing informational acknowledgement ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785e02c seq 000000d3 17 10.1.1.1->10.1.1.2:500 ike 0: unknown SPI a785e03d 16 10.1.2.2:500->10.1.2.1 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: ignoring invalid SPI a785e03d, IPsec SA just negotiated ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL id=6f5926dd59973611/fffd5a84c726669c:000001a5 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: received informational request ike 0:DR_Optus:4505: send INFORMATIONAL_RESPONSE ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0:DR_Optus: link is idle 17 10.1.1.1->10.1.1.2:500 dpd=1 seqno=1246 ike 0:DR_Optus:4505: send IKEv2 DPD probe ike 0:DR_Optus:4505: initiator creating new child request ike 0:DR_Optus:89220: sending NOTIFY msg ike 0:DR_Optus:4505:89220: send informational ike 0:DR_Optus:4505: send INFORMATIONAL ike 0:DR_Optus:4505: sent IKE msg (INFORMATIONAL): 10.1.1.1:500->10.1.1.2:500, len=60 ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=6f5926dd59973611/fffd5a84c726669c:000001a9 len=60 ike 0: found DR_Optus 10.1.1.1 17 -> 10.1.1.2:500 ike 0:DR_Optus:4505: clear pending DPD seqno=4678 ike 0:DR_Optus:4505: received informational response ike 0:DR_Optus:89220: received NOTIFY acknowledgement ike 0:DR_Optus:4505:89220: processing informational acknowledgement ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785e02c seq 000000d4 17 10.1.1.1->10.1.1.2:500 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL id=18c352027710aa5f/793ce8c0694bdaf7:00000265 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: received informational request ike 0:DR_Uecomm:4506: send INFORMATIONAL_RESPONSE ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL_RESPONSE): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0:DR_Uecomm: link is idle 16 10.1.2.1->10.1.2.2:500 dpd=1 seqno=9df7 ike 0:DR_Uecomm:4506: send IKEv2 DPD probe ike 0:DR_Uecomm:4506: initiator creating new child request ike 0:DR_Uecomm:89221: sending NOTIFY msg ike 0:DR_Uecomm:4506:89221: send informational ike 0:DR_Uecomm:4506: send INFORMATIONAL ike 0:DR_Uecomm:4506: sent IKE msg (INFORMATIONAL): 10.1.2.1:500->10.1.2.2:500, len=60 ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16.... ike 0: IKEv2 exchange=INFORMATIONAL_RESPONSE id=18c352027710aa5f/793ce8c0694bdaf7:00000207 len=60 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506: clear pending DPD seqno=40439 ike 0:DR_Uecomm:4506: received informational response ike 0:DR_Uecomm:89221: received NOTIFY acknowledgement ike 0:DR_Uecomm:4506:89221: processing informational acknowledgement ike 0: unknown SPI a785e03d 16 10.1.2.2:500->10.1.2.1 ike 0: found DR_Uecomm 10.1.2.1 16 -> 10.1.2.2:500 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: ignoring invalid SPI a785e03d, IPsec SA just negotiated deb ike 0:DR_Optus: invalid ESP 1 (HMAC) SPI a785e02c seq 000000d6 17 10.1.1.1->10.1.1.2:500 dis

[ede_pfau]

ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: src 0 7 0.0.0.0-255.255.255.255 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: dst 0 7 0.0.0.0-255.255.255.255 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: add IPsec SA: SPIs=a785e03d/c1e6fc11 ike 0:DR_Uecomm:4506:DR_Uecomm_P2:89217: failed to add SA, error 22: Invalid argument

hard to tell from that little information but I' ll guess: the quick mode selectors on DR_Uecomm are 0.0.0.0 both src and dst. Can the second tunnel cope with that? Why don' t you specify the correct subnets of both sides here? It' s not only a selector for the IKE init but also sets up a proxy. If you have 2 of this it might be ambiguous. Secondly: do I interpret this right that you have the same subnet at both ends for each tunnel? Did that work at all?

ike 0: comes 10.1.2.2:500->10.1.2.1:500,ifindex=16....

ike 0: comes 10.1.1.2:500->10.1.1.1:500,ifindex=17....

[darrencarr]

Issue is now resolved. The P2 of the two IPSec tunnels had some how merged into one? No idea how this could happen. Anyway, contacted Fortigate, the fix was to reboot the firewalls at each end. They seem to think it was a HA problem? I am applying an update this weekend on the advice of Fortinet. Cheers