IP Sec VPN Paloalto - Mikrotik

[Tarczynski-SA]

Hi!

I have a situation that is doing my head in, and I need some help.

I have an installation which looks like this

"A" end - Palo Alto Active/Passive cluster, public IP for IPSec VPN termination

"B" end - Mikrotik public IP for IPSec VPN termination

IPSec Tunnel not work. 

The police 1 phase is accepted. But what this?

2019-05-16 14:31:43.017 +0200 [DEBG]: { 15: 39}: keyacquire ignored due to throttling (39 sec ago).

See debug palo:

2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: begin.
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: seen nptype=1(sa)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: seen nptype=13(vid)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: seen nptype=13(vid)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: succeed.
2019-05-16 07:49:29.372 +0200 [INFO]: { 15: }: received Vendor ID: CISCO-UNITY
2019-05-16 07:49:29.372 +0200 [INFO]: { 15: }: received Vendor ID: DPD
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: remote supports DPD
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: total SA len=56
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: begin.
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: seen nptype=2(prop)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: succeed.
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: proposal #1 len=48
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: begin.
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: seen nptype=3(trns)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: succeed.
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: transform #1 len=40
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Life Type, flag=0x8000, lorv=seconds
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Life Duration, flag=0x0000, lorv=4
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Encryption Algorithm, flag=0x8000, lorv=AES
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: encryption(aes)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Key Length, flag=0x8000, lorv=256
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Authentication Method, flag=0x8000, lorv=PSK
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Hash Algorithm, flag=0x8000, lorv=SHA512
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Group Description, flag=0x8000, lorv=DH14
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: pair 1:
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: 0xffdc0145e0: next=(nil) tnext=(nil)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: proposal #1: 1 transform
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: prop#=1, prot-id=ISAKMP, spi-size=0, #trns=1
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: trns#=1, trns-id=IKE
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Life Type, flag=0x8000, lorv=seconds
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Life Duration, flag=0x0000, lorv=4
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Encryption Algorithm, flag=0x8000, lorv=AES
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Key Length, flag=0x8000, lorv=256
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Authentication Method, flag=0x8000, lorv=PSK
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Hash Algorithm, flag=0x8000, lorv=SHA512
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: type=Group Description, flag=0x8000, lorv=DH14
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: Compared: DB:Peer
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: (lifetime = 86400:86400)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: (lifebyte = 0:0)
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: enctype = AES:AES
2019-05-16 07:49:29.372 +0200 [DEBG]: { 15: }: (encklen = 256:256)
...skipping...
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: pair 1:
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: 0xffdc00f7e0: next=(nil) tnext=(nil)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: proposal #1: 1 transform
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: prop#=1, prot-id=ISAKMP, spi-size=0, #trns=1
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: trns#=1, trns-id=IKE
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Life Type, flag=0x8000, lorv=seconds
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Life Duration, flag=0x0000, lorv=4
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Encryption Algorithm, flag=0x8000, lorv=AES
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Key Length, flag=0x8000, lorv=256
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Authentication Method, flag=0x8000, lorv=PSK
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Hash Algorithm, flag=0x8000, lorv=SHA512
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: type=Group Description, flag=0x8000, lorv=DH14
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: Compared: DB:Peer
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: (lifetime = 86400:86400)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: (lifebyte = 0:0)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: enctype = AES:AES
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: (encklen = 256:256)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: hashtype = SHA512:SHA512
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: authmethod = PSK:PSK
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: dh_group = DH14:DH14
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: an acceptable proposal found.
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: PH1 state changed: 1 to 2 @ph1_set_next_state
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: add payload of len 56, next type 13(vid)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: add payload of len 16, next type 13(vid)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: add payload of len 16, next type 13(vid)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: add payload of len 16, next type 0(none)
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 0
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: add packet caf8ad1a:20 size 128, rcp 2
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: }: PH1 state changed: 2 to 3 @ph1_set_next_state
2019-05-16 14:31:24.421 +0200 [DEBG]: { 15: 39}: keyacquire ignored due to throttling (20 sec ago).
2019-05-16 14:31:25.027 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:25.027 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 1
2019-05-16 14:31:26.026 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:26.027 +0200 [DEBG]: { 15: }: resend phase1 packet a0f4050f26c4283d:b4e9fdfcd28f3714, retry 5
2019-05-16 14:31:27.016 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:27.017 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 2
2019-05-16 14:31:30.026 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:30.027 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 3
2019-05-16 14:31:30.027 +0200 [DEBG]: { 15: }: del packet 3c19046c:20 size 128, rcp 1
2019-05-16 14:31:34.425 +0200 [INFO]: the packet is retransmitted from 2.2.2.2[500] to 1.1.1.1[500].
2019-05-16 14:31:34.425 +0200 [DEBG]: { 15: 39}: keyacquire ignored due to throttling (30 sec ago).
2019-05-16 14:31:35.027 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:35.027 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 4
2019-05-16 14:31:39.027 +0200 [PNTF]: { 15: }: ====> PHASE-1 NEGOTIATION FAILED AS RESPONDER, MAIN MODE <====
====> Failed SA: 1.1.1.1[500]-2.2.2.2[500] cookie:a0f4050f26c4283d:b4e9fdfcd28f3714 <==== Due to timeout.
2019-05-16 14:31:39.027 +0200 [INFO]: { 15: }: ====> PHASE-1 SA DELETED <====
====> Deleted SA: 1.1.1.1[500]-2.2.2.2[500] cookie:a0f4050f26c4283d:b4e9fdfcd28f3714 <====
2019-05-16 14:31:43.017 +0200 [DEBG]: { 15: }: 148 bytes from 1.1.1.1[500] to 2.2.2.2[500]
2019-05-16 14:31:43.017 +0200 [DEBG]: { 15: }: resend phase1 packet 2190b5cc95b5f4d2:060325efd628efe4, retry 5
2019-05-16 14:31:43.017 +0200 [DEBG]: { 15: 39}: keyacquire ignored due to throttling (39 sec ago).
2019-05-16 14:31:44.422 +0200 [INFO]: the packet is retransmitted from 2.2.2.2[500] to 1.1.1.1[500].
2019-05-16 14:31:50.016 +0200 [DEBG]: { 15: }: del packet caf8ad1a:20 size 128, rcp 0
2019-05-16 14:31:54.425 +0200 [DEBG]: { 15: }: malformed cookie received. it has to be as the initiator. 2190b5cc95b5f4d2:060325efd628efe4
2019-05-16 14:31:56.027 +0200 [PNTF]: { 15: }: ====> PHASE-1 NEGOTIATION FAILED AS RESPONDER, MAIN MODE <====
====> Failed SA: 1.1.1.1[500]-2.2.2.2[500] cookie:2190b5cc95b5f4d2:060325efd628efe4 <==== Due to timeout.
2019-05-16 14:31:56.027 +0200 [INFO]: { 15: }: ====> PHASE-1 SA DELETED <====
====> Deleted SA: 1.1.1.1[500]-2.2.2.2[500] cookie:2190b5cc95b5f4d2:060325efd628efe4 <====

[BPry]

@Tarczynski-SA,

Do you by chance have multiple proxy-ids configured for this tunnel? When you have a lot of proxy-ids you'll sometimes see this message when the proxy-ids are all attempting to rekey depending on the number in use and the platform in question. It isn't that big of a deal as the system will simply perform a rekey for that proxy-id at a latter time. 

[Tarczynski-SA]

I configured this tunnel in EVE-NG virtual environment and it works. I haven't any problems.

But in the real network didn't work.

About proxy ID:

[OtakarKlier]

Hello,

I would verify the proxy ID's from the other side. If they dont match exactly, then they wont work.

Regards,

[BPry]

@Tarczynski-SA,

I'd agree with @OtakarKlier  here and say that something is likely misconfigured. With just one set of proxy IDs I wouldn't expect to see any throttling unless you have multiple IPSec Tunnels configured besides this one already. 

[Tarczynski-SA]

I have a problem with phase 1 IKE in the Main mode (6 messages):

1.  Ike polices exchange - 2 messages -Ok

2.  DH algorithm - created shared secret - created SKEYID - skeyid_a, skeyid_e,skeyid_d 

3.  Peer Authentication - pre-shared key and I thinking here a problem in a log - key acquire ignored due to throttling, but why I don't know 😞

Just peers can't authenticate each other

[Tarczynski-SA · Accepted solution]

Just as the wrong pre-shared key on phase 1 - 2019-05-16 14:31:43.017 +0200 [DEBG]: { 15: 39}: key acquire ignored due to throttling

Thanks.