Troubleshooting IPsec Logs¶
Note
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
Note
Changing logging options is not disruptive to IPsec tunnels.
Tip
Though this section assumes log messages are obtained from the IPsec log, using a manual connection attempt (Manually connect 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 Troubleshooting IPsec Logs 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 phase 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 Main mode.
Log output from the initiator:
charon: 15[IKE] initiating Aggressive Mode IKE_SA con2[1] to 203.0.113.5
charon: 15[IKE] received AUTHENTICATION_FAILED error notify
charon: 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 reasons
charon: 13[ENC] generating INFORMATIONAL_V1 request 2940146627 [ N(AUTH_FAILED) ]
Note that the logs on the responder state clearly that Aggressive mode is disabled, which is a good clue that the mode is mismatched.
In the reverse case, if the side set for Main mode initiates, the tunnel to a firewall running pfSense software will establish since 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 found
charon: 12[ENC] generating INFORMATIONAL_V1 request 4216246776 [ HASH N(AUTH_FAILED) ]
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_1024
charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
charon: 14[IKE] no proposal found
charon: 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_1024
charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
charon: 14[IKE] no proposal found
charon: 14[ENC] generating INFORMATIONAL_V1 request 2774552374 [ N(NO_PROP) ]
The hash algorithm is indicated by the HMAC 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_8192
charon: 14[CFG] configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1024
charon: 14[IKE] no proposal found
charon: 14[ENC] generating INFORMATIONAL_V1 request 316473468 [ N(NO_PROP) ]
DH group is indicated by the MODP 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|/0
charon: 08[CFG] proposing traffic selectors for other:
charon: 08[CFG] 10.5.0.0/24|/0
charon: 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|/0
charon: 08[CFG] proposing traffic selectors for us:
charon: 08[CFG] 10.5.1.0/24|/0
charon: 08[CFG] proposing traffic selectors for other:
charon: 08[CFG] 10.3.0.0/24|/0
charon: 08[IKE] no matching CHILD_SA config found
charon: 08[IKE] queueing INFORMATIONAL task
charon: 08[IKE] activating new tasks
charon: 08[IKE] activating INFORMATIONAL task
charon: 08[ENC] generating INFORMATIONAL_V1 request 1136605099 [ HASH N(INVAL_ID) ]
The responder logs lists 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_SEQ
charon: 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 found
charon: 13[CFG] received proposals: ESP:AES_CBC_128/HMAC_SHA1_96/NO_EXT_SEQ
charon: 13[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
charon: 13[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSEN
charon: 13[IKE] queueing INFORMATIONAL task
charon: 13[IKE] activating new tasks
charon: 13[IKE] activating INFORMATIONAL task
charon: 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_SEQ
charon: 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 found
charon: 11[CFG] received proposals: ESP:AES_CBC_256/HMAC_SHA2_512_256/NO_EXT_SEQ
charon: 11[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
charon: 11[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSEN
charon: 11[IKE] queueing INFORMATIONAL task
charon: 11[IKE] activating new tasks
charon: 11[IKE] activating INFORMATIONAL task
charon: 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 found
charon: 08[CFG] received proposals: ESP:AES_CBC_256/HMAC_SHA1_96/MODP_2048/NO_EXT_SEQ
charon: 08[CFG] configured proposals: ESP:AES_CBC_256/HMAC_SHA1_96/NO_EXT_SEQ
charon: 08[IKE] no matching proposal found, sending NO_PROPOSAL_CHOSEN
charon: 08[ENC] generating INFORMATIONAL_V1 request 3861985833 [ HASH N(NO_PROP) ]
Perfect Forward Secrecy (PFS) works like DH groups on 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.
Note
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.
Note
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 NAT
charon: 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 setting to IP
Address and then enter the pre-NAT IP address, which in this example is
192.0.2.10.