05-16-2019 05:47 AM
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 <====
