Symptom
This document explains the various error logs seen during the IPSec tunnel negotiation issues.
Environment
PA firewall version 8.1 and above
Resolution
The following debug is enabled to get the debug logs shown in the document.
Primary-Tunnel is the IPSec tunnel name usually refers to the Phase 2.
Primary-GW is the IKE Gateway that holds the Phase 1 settings.
> debug ike tunnel Primary-Tunnel on debug
> debug ike gateway Primary-GW on debug
The debug can be turned off with the below commands.
> debug ike tunnel Primary-Tunnel off
> debug ike gateway Primary-GW off
To view the debugs you can use the below command on the cli.
> tail follow yes mp-log ikemgr.log
The logs can also be found under var/log/pan/ikemgr.log while checking on the Tech Support File.
Note : “<<<<” indicates comments and is not part of the logs
The system logs are taken from the CLI. When checking the system logs on cli the “object” and “event” ID section will be incomplete.
Hence use the logs below as reference and check the system logs under the GUI.
Only snippets of the Debug logs are given below which give direct indication of the issue. There will be more logs coming up on the debug which can also be checked for complete understanding of the issue.
Phase 1 and Phase 2 related error logs :
1. Mismatch in Proposal Phase 1
Debug Log :
2020-01-28 01:10:42.679 -0800 [PNTF]: { 9: }: ====> PHASE-1 NEGOTIATION STARTED AS RESPONDER, MAIN MODE <====
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: Compared: DB:Peer
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: (lifetime = 28800:28800)
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: (lifebyte = 0:0)
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: enctype = AES:AES
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: (encklen = 256:128) <<<< Local is AES 256, Received AES 128
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: hashtype = SHA256:SHA256
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: authmethod = PSK:PSK
2020-01-28 01:10:42.679 -0800 [DEBG]: { 9: }: dh_group = DH14:DH14
2020-01-28 01:10:42.679 -0800 [PERR]: { 9: }: no suitable proposal found.
2020-01-28 01:10:42.679 -0800 [PERR]: { 9: }: 10.75.75.78[500] – 10.76.76.100[500]:(nil) failed to get valid proposal.
2020-01-28 01:10:42.679 -0800 [PERR]: { 9: }: failed to process packet.
System log :
2020/01/28 01:11:08 info vpn Primary-GW ike-nego-p1-fail-common 0 IKE phase-1 negotiation is failed. no suitable proposal found in peer’s SA payload.
2. Peer not responding for Phase 1:
Debug logs :
2020-01-28 01:52:02.000 -0800 [PNTF]: { 9: }: ====> PHASE-1 NEGOTIATION STARTED AS INITIATOR, MAIN MODE <====
2020-01-28 01:52:02.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 0
2020-01-28 01:52:03.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 1
2020-01-28 01:52:05.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 2
2020-01-28 01:52:08.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 3
2020-01-28 01:52:13.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 4
2020-01-28 01:52:21.000 -0800 [DEBG]: { 9: }: resend phase1 packet eab5be199890e4cc:0000000000000000, retry 5
2020-01-28 01:52:34.000 -0800 [PNTF]: { 9: }: ====> PHASE-1 NEGOTIATION FAILED AS INITIATOR, MAIN MODE <====
====> Failed SA: 10.75.75.78[500]-10.76.76.100[500] cookie:eab5be199890e4cc:0000000000000000 <==== Due to timeout.
System Logs :
2020/01/28 01:52:33 info vpn Primary-GW ike-nego-p1-fail 0 IKE phase-1 negotiation is failed as initiator, main mode. Failed SA: 10.75.75.78[500]-10.76.76.100[500] cookie:eab5be199890e4cc:0000000000000000. Due to timeout.
0000000000000000 <<<< Indicates that this is the Message 1 from the PA firewall and there is no reply for this message from the peer.
3. Peer ID incorrect :
Debug logs :
2020-01-28 01:58:19.320 -0800 [PERR]: { 9: }: peer identifier (type ipaddr [10.23.23.1]) does not match remote Primary-GW
2020-01-28 01:58:19.320 -0800 [PERR]: { 9: }: 10.75.75.78[500] – 10.76.76.100[500]:(nil) invalid ID payload.
2020-01-28 01:58:19.320 -0800 [PERR]: { 9: }: failed to process packet.
System logs :
2020/01/28 01:58:45 critical vpn Primary-GW ike-nego-p1-fail-common 0 IKE phase-1 negotiation is failed. Peer’s ID payload 10.23.23.1 (type ipaddr) does not match a configured IKE gateway.
4. Mismatch in Proposal Phase 2
A. Auth Algorithm Mismatch :
Local (SHA1) — Remote (SHA256)
Debug Logs :
2020-01-28 01:17:46.629 -0800 [DEBG]: { 9: }: authtype mismatched: my:hmac-sha peer:hmac-sha256
2020-01-28 01:17:46.629 -0800 [PERR]: { : 22}: not matched
2020-01-28 01:17:46.629 -0800 [PERR]: { : 22}: no suitable policy found.
2020-01-28 01:17:46.629 -0800 [ERR ]: { : 22}: failed to pre-process packet.
System Logs :
2020/01/28 01:17:59 info vpn Primary-GW ike-send-notify 0 IKE protocol notification message sent: NO-PROPOSAL-CHOSEN (14).
2020/01/28 01:17:59 info vpn Primary-Tunnel ike-nego-p2-proposal-bad 0 IKE phase-2 negotiation failed when processing SA payload. no suitable proposal found in peer’s SA payload.
B. Encryption Algorithm Mismatch:
Debug Logs :
Local (AES 128)—— Remote (AES 256)
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: peer’s single bundle:
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: (proto_id=ESP spisize=4 spi=e7550502 spi_p=00000000 encmode=Tunnel reqid=0:0)
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: (trns_id=AES encklen=256 authtype=hmac-sha256)
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: my single bundle:
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: (proto_id=ESP spisize=4 spi=00000000 spi_p=00000000 encmode=Tunnel reqid=0:0)
2020-01-28 01:20:26.549 -0800 [DEBG]: { : 22}: (trns_id=AES encklen=128 authtype=hmac-sha256)
2020-01-28 01:20:26.549 -0800 [DEBG]: { 9: }: key length mismatched, mine:128 peer:256.
2020-01-28 01:20:26.549 -0800 [PERR]: { : 22}: not matched
2020-01-28 01:20:26.549 -0800 [PERR]: { : 22}: no suitable policy found.
2020-01-28 01:20:26.549 -0800 [ERR ]: { : 22}: failed to pre-process packet.
Local (3DES) ——- Remote (AES 256)
2020-01-28 01:22:49.459 -0800 [DEBG]: { 9: }: trns_id mismatched: my:3DES peer:AES
2020-01-28 01:22:49.459 -0800 [PERR]: { : 22}: not matched
2020-01-28 01:22:49.459 -0800 [PERR]: { : 22}: no suitable policy found.
2020-01-28 01:22:49.459 -0800 [ERR ]: { : 22}: failed to pre-process packet.
C. PFS mismatch :
Local (No PFS) ——- Remote (PFS group2)
2020-01-28 01:25:00.399 -0800 [PNTF]: { 9: }: ====> PHASE-2 NEGOTIATION STARTED AS RESPONDER, (QUICK MODE) <====
2020-01-28 01:25:00.399 -0800 [PERR]: { 9: }: pfs group mismatched: my:0 peer:2
2020-01-28 01:25:00.399 -0800 [PERR]: { : 22}: not matched
2020-01-28 01:25:00.399 -0800 [PERR]: { : 22}: no suitable policy found.
2020-01-28 01:25:00.399 -0800 [ERR ]: { : 22}: failed to pre-process packet.
System logs :
2020/01/28 01:20:42 info vpn Primary-GW ike-send-notify 0 IKE protocol notification message sent: NO-PROPOSAL-CHOSEN (14).
2020/01/28 01:20:42 info vpn Primary-Tunnel ike-nego-p2-proposal-bad 0 IKE phase-2 negotiation failed when processing SA payload. no suitable proposal found in peer’s SA payload.
D. Proxy ID mismatch :
The below Proxy ID mismatch log can be seen only when PA firewall is the Responder of the Phase 1
Debug log :
2020-01-28 01:07:50.655 -0800 [ERR ]: { 9: }: can’t find matching selector
2020-01-28 01:07:50.655 -0800 [PERR]: { 9: }: failed to get sainfo.
System logs :
2020/01/28 00:56:51 info vpn Primary-GW ike-nego-p2-proxy-id-bad 0 IKE phase-2 negotiation failed when processing proxy ID. cannot find matching phase-2 tunnel for received proxy ID. received local id: 0.0.0.0/0 type IPv4_subnet protocol 0 port 0, received remote id: 0.0.0.0/0 type IPv4_subnet protocol 0 port 0.
If Firewall is Initiator the system log as below can be seen.
The log does not indicate that the issue is exactly with Proxy id.
2020/01/28 00:55:26 info vpn Primary-Tunnel:proxy1 ike-nego-p2-fail 0 IKE phase-2 negotiation is failed as initiator, quick mode. Failed SA: 10.75.75.78[500]-10.76.76.100[500] message id:0x8427B6F7. Due to negotiation timeout.
Tunnel Monitoring Failure :
System log:
2020/01/28 19:00:34 critical vpn Primary-Tunnel tunnel-status-down 0 Tunnel Primary-Tunnel is down
No Debug logs will be seeen.
DPD failure :
Below debug shown will be seen with the below settings under Dead Peer Detection. The number of retry logs will vary as per the setting.
Interval 2 seconds
Retry 3 seconds
Debug logs :
2020-01-29 00:55:30.000 -0800 [DEBG]: { 9: }: DPD monitoring…. ip 0 0
2020-01-29 00:55:30.000 -0800 [DEBG]: { 9: }: DPD R-U-There sent (0)
2020-01-29 00:55:33.000 -0800 [DEBG]: { 9: }: DPD monitoring…. ip 0 1
2020-01-29 00:55:33.000 -0800 [DEBG]: { 9: }: DPD R-U-There sent (0)
2020-01-29 00:55:36.000 -0800 [DEBG]: { 9: }: DPD monitoring…. ip 0 2
2020-01-29 00:55:36.000 -0800 [DEBG]: { 9: }: DPD R-U-There sent (0)
2020-01-29 00:55:39.000 -0800 [DEBG]: { 9: }: DPD monitoring…. ip 0 3
2020-01-29 00:55:39.000 -0800 [DEBG]: { 9: }: DPD: remote seems to be dead
2020-01-29 00:55:39.000 -0800 [DEBG]: { 9: }: sendto Information delete.
2020-01-29 00:55:39.000 -0800 [INFO]: { 9: }: ====> PHASE-1 SA DELETED <====
====> Deleted SA: 10.75.75.78[500]-10.76.76.100[500] cookie:666b567f1c505723:9bd08e2fb85b7260 <====
2020-01-29 00:55:39.000 -0800 [INFO]: { 9: 22}: DPD down, rekey vpn tunnel <Primary-Tunnel>
System logs :
2020/01/29 00:55:38 info vpn Primary-GW ike-send-p1-delete 0 IKE protocol phase-1 SA delete message sent to peer. cookie:666b567f1c505723:9bd08e2fb85b7260.
2020/01/29 00:55:38 low vpn Primary-GW ike-nego-p1-dpd-dn 0 IKE phase-1 SA is down determined by DPD.
Ref: IKEv1 VPN error logs – Troubleshooting – Knowledge Base – Palo Alto Networks