How to troubleshoot IPsec Logs on Netgate router

Authored by: Support.com Tech Pro Team

1. Introduction

How to troubleshoot IPsec Logs on Netgate router

2. Resolution

IPsec logging

Examples presented in this document contain logs edited for brevity but significant messages remain.

Logging for IPsec can provide useful information. To configure IPsec logging for diagnosing tunnel issues with pfSense® software, the following procedure yields the best balance of information:

• Navigate to VPN > IPsec on the Advanced Settings tab
• Set IKE SA, IKE Child SA, and Configuration Backend to Diag
• Set all other log settings to Control
• Click Save

Changing logging options is not disruptive to IPsec tunnels. 

Though this section assumes log messages are obtained from the IPsec log, using a manual connection attempt (Manually connecting IPsec from the shell) can yield more focused results when initiating. When initiating manually using a shell command the messages are printed to the console and not mixed with logs from other connections, making it much simpler to find relevant log messages. 

IPsec log interpretation

The IPsec logs available at Status > System Logs, on the IPsec tab, contain a record of the tunnel connection process and some messages from ongoing tunnel maintenance activity. Some typical log entries are listed in this section, both good and bad. The main things to look for are key phrases that indicate which part of a connection worked. If “IKE_SA … established” is present in the log, that means phase 1 was completed successfully and a Security Association was negotiated. If “CHILD_SA … established” is present, then phase 2 has also been completed and the tunnel is up.

In the following examples, the logs have been configured as listen in IPsec logging and irrelevant messages may be omitted. Bear in mind that these are samples and the specific ID numbers, IP addresses, and so forth will vary.

Successful connections

When a tunnel has been successfully established both sides will indicate that an IKE SA and a Child SA have been established. When multiple phases 2 definitions are present with IKEv1, a child SA is negotiated for each phase 2 entry.

Log output from the initiator:

charon: 09[IKE] IKE_SA con2[11] established between 192.0.2.90[192.0.2.90]...192.0.2.74[192.0.2.74]charon: 09[IKE] CHILD_SA con2{2} established with SPIs cf4973bf_i c1cbfdf2_o and TS 192.168.48.0/24|/0 === 10.42.42.0/24|/0

Log output from the responder:

charon: 03[IKE] IKE_SA con1[19] established between 192.0.2.74[192.0.2.74]...192.0.2.90[192.0.2.90]charon: 16[IKE] CHILD_SA con1{1} established with SPIs c1cbfdf2_i cf4973bf_o and TS 10.42.42.0/24|/0 === 192.168.48.0/24|/0

Failed connection examples

These examples show failed connections for varying reasons. In most cases, it is clear from the examples that the initiator does not receive messages about specific items that do not match, so the responder logs are much more informative. This is done to protect the security of the tunnel, it would be insecure to provide messages to a potential attacker that would give them information about how the tunnel is configured.

Phase 1 main/aggressive mismatch

In this example, the initiator is set for Aggressive mode while the responder is set for the Main mode.

Log output from the initiator:

charon: 15[IKE] initiating Aggressive Mode IKE_SA con2[1] to 203.0.113.5charon: 15[IKE] received AUTHENTICATION_FAILED error notifycharon: 13[ENC] parsed INFORMATIONAL_V1 request 1215317906 [ N(AUTH_FAILED) ]charon: 13[IKE] received AUTHENTICATION_FAILED error notify

Log output from the responder:

charon: 13[IKE] Aggressive Mode PSK disabled for security reasonscharon: 13[ENC] generating INFORMATIONAL_V1 request 2940146627 [ N(AUTH_FAILED) ]

Note that the logs on the responder state clearly that the Aggressive mode is disabled, which is a good clue that the mode is mismatched.

In the reverse case, if the side set for the Main mode initiates, the tunnel to a firewall running pfSense software will establish since the Main mode is more secure.

Phase 1 identifier mismatch

When the identifier does not match the initiator only shows that the authentication failed, but does not give a reason. The responder states that it is unable to locate a peer, which indicates that it could not find a matching phase 1, which implies that no matching identifier could be located.

Log output from the initiator:

charon: 10[ENC] parsed INFORMATIONAL_V1 request 4216246776 [ HASH N(AUTH_FAILED) ]charon: 10[IKE] received AUTHENTICATION_FAILED error notify

Log output from the responder:

charon: 12[CFG] looking for pre-shared key peer configs matching 203.0.113.5...198.51.100.3[someid]charon: 12[IKE] no peer config foundcharon: 12[ENC] generating INFORMATIONAL_V1 request 4216246776 [ HASH N(AUTH_FAILED) ]

Phase 1 pre-shared key mismatch

A mismatched pre-shared key can be tough to diagnose. An error stating the fact that this value is mismatched is not printed in the log, instead, these messages are shown:

Log output from the initiator:

charon: 09[ENC] invalid HASH_V1 payload length, decryption failed?charon: 09[ENC] could not decrypt payloadscharon: 09[IKE] message parsing failed

Log output from the responder:

charon: 09[ENC] invalid ID_V1 payload length, decryption failed?charon: 09[ENC] could not decrypt payloadscharon: 09[IKE] message parsing failed

When the above log messages are present check the Pre-Shared Key value on both sides to ensure they match.

Phase 1 encryption algorithm mismatch

Log output from the initiator:

charon: 14[ENC] parsed INFORMATIONAL_V1 request 3851683074 [ N(NO_PROP) ]charon: 14[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 14[CFG] received proposals: IKE:AES_CBC_128/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024charon: 14[IKE] no proposal foundcharon: 14[ENC] generating INFORMATIONAL_V1 request 3851683074 [ N(NO_PROP) ]

In this case, the log entry shows the problem exactly: The initiator was set for AES 128 encryption, and the responder is set for AES 256. Set both to matching values and then try again.

Phase 1 hash algorithm mismatch

Log output from the initiator:

charon: 10[ENC] parsed INFORMATIONAL_V1 request 2774552374 [ N(NO_PROP) ]charon: 10[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 14[CFG] received proposals: IKE:AES_CBC_256/MODP_1024charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024charon: 14[IKE] no proposal foundcharon: 14[ENC] generating INFORMATIONAL_V1 request 2774552374 [ N(NO_PROP) ]

The hash algorithm is indicated by the HMAC a portion of the logged proposals. As can be seen above, the received and configured proposals do not have matching HMAC entries. Set them both to match and try again.

Phase 1 DH group mismatch

Log output from the initiator:

charon: 11[ENC] parsed INFORMATIONAL_V1 request 316473468 [ N(NO_PROP) ]charon: 11[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 14[CFG] received proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_8192charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024charon: 14[IKE] no proposal foundcharon: 14[ENC] generating INFORMATIONAL_V1 request 316473468 [ N(NO_PROP) ]

DH group is indicated by the MODP a portion of the listed proposal. As indicated by the log messages, the initiator was set for 8192 (Group 18) and the responder was set for 1024 (Group 2). This error can be corrected by setting the DH group setting on both ends of the tunnel to a matching value.

Phase 2 network mismatch

In the following example, the phase 2 entry on the initiator side is set for 10.3.0.0/24 to 10.5.0.0/24. The responder is not set to match as it lists 10.5.1.0/24 instead.

Log output from the initiator:

charon: 08[CFG] proposing traffic selectors for us:charon: 08[CFG] 10.3.0.0/24|/0charon: 08[CFG] proposing traffic selectors for other:charon: 08[CFG] 10.5.0.0/24|/0charon: 08[ENC] generating QUICK_MODE request 316948142 [ HASH SA No ID ID ]charon: 08[NET] sending packet: from 198.51.100.3[500] to 203.0.113.5[500] (236 bytes)charon: 08[NET] received packet: from 203.0.113.5[500] to 198.51.100.3[500] (76 bytes)charon: 08[ENC] parsed INFORMATIONAL_V1 request 460353720 [ HASH N(INVAL_ID) ]charon: 08[IKE] received INVALID_ID_INFORMATION error notify

Log output from the responder:

charon: 08[ENC] parsed QUICK_MODE request 2732380262 [ HASH SA No ID ID ]charon: 08[CFG] looking for a child config for 10.5.0.0/24|/0 === 10.3.0.0/24|/0charon: 08[CFG] proposing traffic selectors for us:charon: 08[CFG] 10.5.1.0/24|/0charon: 08[CFG] proposing traffic selectors for other:charon: 08[CFG] 10.3.0.0/24|/0charon: 08[IKE] no matching CHILD_SA config foundcharon: 08[IKE] queueing INFORMATIONAL taskcharon: 08[IKE] activating new taskscharon: 08[IKE] activating INFORMATIONAL taskcharon: 08[ENC] generating INFORMATIONAL_V1 request 1136605099 [ HASH N(INVAL_ID) ]

The responder logs list both the networks it received (child config line in the log) and what it has configured locally (proposing traffic selectors for... lines in the log). By comparing the two, a mismatch can be spotted. The no matching CHILD_SA config found line in the log will always be present when this mismatch occurs and that directly indicates that it could not find a phase 2 definition to match the values received from the initiator.

Phase 2 encryption algorithm mismatch

Log output from the initiator:

charon: 14[CFG] configured proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQcharon: 14[ENC] generating QUICK_MODE request 759760112 [ HASH SA No ID ID ]charon: 14[NET] sending packet: from 198.51.100.3[500] to 203.0.113.5[500] (188 bytes)charon: 14[NET] received packet: from 203.0.113.5[500] to 198.51.100.3[500] (76 bytes)charon: 14[ENC] parsed INFORMATIONAL_V1 request 1275272345 [ HASH N(NO_PROP) ]charon: 14[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 13[CFG] selecting proposal:charon: 13[CFG] no acceptable ENCRYPTION_ALGORITHM foundcharon: 13[CFG] received proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQcharon: 13[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQcharon: 13[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSENcharon: 13[IKE] queueing INFORMATIONAL taskcharon: 13[IKE] activating new taskscharon: 13[IKE] activating INFORMATIONAL taskcharon: 13[ENC] generating INFORMATIONAL_V1 request 1275272345 [ HASH N(NO_PROP) ]

In this case, the initiator receives a message that the responder could not find a suitable proposal (received NO_PROPOSAL_CHOSEN), and from the responder logs, it is obvious this was due to the sites being set for different encryption types, AES 128 on one side and AES 256 on the other.

Phase 2 hash algorithm mismatch

Log output from the initiator:

charon: 10[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA2_512_256/NO_EXT_SEQcharon: 10[ENC] generating QUICK_MODE request 2648029707 [ HASH SA No ID ID ]charon: 10[NET] sending packet: from 198.51.100.3[500] to 203.0.113.5[500] (188 bytes)charon: 10[NET] received packet: from 203.0.113.5[500] to 198.51.100.3[500] (76 bytes)charon: 10[ENC] parsed INFORMATIONAL_V1 request 757918402 [ HASH N(NO_PROP) ]charon: 10[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 11[CFG] selecting proposal:charon: 11[CFG] no acceptable INTEGRITY_ALGORITHM foundcharon: 11[CFG] received proposals: ESP:AES_CBC_256/HMAC_SHA2_512_256/NO_EXT_SEQcharon: 11[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQcharon: 11[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSENcharon: 11[IKE] queueing INFORMATIONAL taskcharon: 11[IKE] activating new taskscharon: 11[IKE] activating INFORMATIONAL taskcharon: 11[ENC] generating INFORMATIONAL_V1 request 757918402 [ HASH N(NO_PROP) ]

Similar to a phase 1 hash algorithm mismatch, the HMAC values in the log entries do not line up. However, the responder also logs a clearer message no acceptable INTEGRITY_ALGORITHM found when this happens in phase 2.

Phase 2 pfs mismatch

Log output from the initiator:

charon: 06[ENC] generating QUICK_MODE request 909980434 [ HASH SA No KE ID ID ]charon: 06[NET] sending packet: from 198.51.100.3[500] to 203.0.113.5[500] (444 bytes)charon: 06[NET] received packet: from 203.0.113.5[500] to 198.51.100.3[500] (76 bytes)charon: 06[ENC] parsed INFORMATIONAL_V1 request 3861985833 [ HASH N(NO_PROP) ]charon: 06[IKE] received NO_PROPOSAL_CHOSEN error notify

Log output from the responder:

charon: 08[CFG] selecting proposal:charon: 08[CFG] no acceptable DIFFIE_HELLMAN_GROUP foundcharon: 08[CFG] received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQcharon: 08[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQcharon: 08[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSENcharon: 08[ENC] generating INFORMATIONAL_V1 request 3861985833 [ HASH N(NO_PROP) ]

Perfect Forward Secrecy (PFS) works like DH groups in phase 1 but is optional. When PFS options do not match a clear message is logged indicating this fact: no acceptable DIFFIE_HELLMAN_GROUP found.

In some cases, if one side has PFS set to off, and the other side has a value set, the tunnel may still establish and work. The mismatch shown above may only be seen if the values mismatch, for example 1 vs. 5. 

Due to the way IPsec negotiates the first child SA will not use the PFS value from phase 2, but the DH group value from phase 1. Subsequent child SA entries or rekeys will use the value from phase 2. Thus, if a tunnel connects OK at first but fails at rekey, ensure the phase 2 PFS values match.

Mismatched identifier with nat

In this case, pfSense software is configured for a Peer Identifier of Peer IP address, but the remote device is actually behind NAT. In this case, strongSwan expects the actual private before-NAT IP address as the identifier.

Log output from the responder:

charon: 10[IKE] remote host is behind NATcharon: 10[IKE] IDir '192.0.2.10' does not match to '203.0.113.245'[...]charon: 10[CFG] looking for pre-shared key peer configs matching 198.51.100.50...203.0.113.245[192.0.2.10]

To correct this condition, change the Peer Identifier set to IP Address and then enter the pre-NAT IP address, which in this example is 192.0.2.10.