Improve debug logging around certificate validation

[iamacarpet]

Is your feature request related to a problem? Please describe.

When using IKEv2 certificate based authentication, if validation fails for the server certificate, the logging is very poor around the reason & it's very difficult to debug - even on the highest debug level, you get a binary dump of the packets, but no explanation of the logic being used for the validation, or a reason it was rejected.

I had a problem where the remote endpoint (also actually running strongSwan on pfSense, and being used for Windows 10/11 AlwaysOn Device Tunnel) was being rejected on Linux clients, even thought it works perfectly on Windows clients, and it was very hard to figure out why.

Eventually, I posted the logs on IRC and user ecsda replied very quickly to say it was the remote server presenting an IP as it's identity rather than the FQDN we were connecting to (and what was listed on the SAN in the certificate).

This validation logic wasn't obvious at all from the logs and even reading the source code: I'm fairly competent reading code, but with limited understanding of the code base & not a lot of time, I couldn't figure it out - it also doesn't seem to be documented anywhere.

Describe the solution you'd like

Better logging, especially at level 1.

Include a simple explanation of what is being validated and if rejected, what caused the rejection.

Describe alternatives you've considered

Hours & hours of debugging that could otherwise be avoided....? :).

Additional context

Relevant snippet of the logs where it fails:

2023-05-19T11:24:08.204436Z INFO charon[778]: 11[ENC] unknown attribute type (27674)
2023-05-19T11:24:08.204953Z INFO charon[778]: 11[ENC] unknown attribute type (27675)
2023-05-19T11:24:08.206668Z INFO charon[778]: 11[ENC] parsed IKE_AUTH response 1 [ IDr CERT CERT AUTH CPRP(ADDR DNS (27674) (27675)) N(ESP_TFC_PAD_N) SA TSi TSr N(MOBIKE_SUP) N(ADD_4_ADDR) ]
2023-05-19T11:24:08.209706Z INFO charon[778]: 11[IKE] received end entity cert "***redacted***"
2023-05-19T11:24:08.212402Z INFO charon[778]: 11[IKE] received issuer cert "***redacted***"
2023-05-19T11:24:08.212552Z INFO charon[778]: 11[IKE] received ESP_TFC_PADDING_NOT_SUPPORTED notify
2023-05-19T11:24:08.214908Z INFO charon[778]: 11[IKE] no trusted RSA public key found for 'x.x.x.x'
2023-05-19T11:24:08.215560Z INFO charon[778]: 11[ENC] generating INFORMATIONAL request 2 [ N(AUTH_FAILED) ]
2023-05-19T11:24:08.216829Z INFO charon[778]: 11[NET] sending packet: from x.x.x.x[4500] to x.x.x.x[4500] (65 bytes)
2023-05-19T11:24:08.217561Z INFO charon[778]: 11[KNL] deleting SAD entry with SPI c080e686
2023-05-19T11:24:08.217870Z INFO charon[778]: 11[KNL] deleted SAD entry with SPI c080e686
2023-05-19T11:24:08.218503Z INFO charon[778]: 08[CFG] vici client 3 disconnected
2023-05-19T11:24:08.219047Z INFO charon[778]: 11[IKE] IKE_SA vpn[1] state change: CONNECTING => DESTROYING

[tobiasbrunner]

Eventually, I posted the logs on IRC and user ecsda replied very quickly to say it was the remote server presenting an IP as it's identity rather than the FQDN we were connecting to (and what was listed on the SAN in the certificate).

That was me and the issue is quite common (i.e. easily identifiable). Actually, it even has its own FAQ entry with a kind of checklist.

However, in your case it has nothing to do with the actual certificate validation. It happens before that because there is no public key available (which could be contained in a certificate, but does not have to be) that matches the peer's identity, which is exactly what the log message states.

[iamacarpet]

I appreciate you linking the FAQ - I wasn't able to find this at the time, even after searching for the relevant string & strongswan together on Google.

That being said, even with the FAQ, it may be obvious to someone who is very familiar with IPsec / strongSwan, but I would have found it very hard to draw that conclusion from what is actually being logged - I agree, now you've pointed it out, I can see where you are saying it did log that, but to the uninitiated, it isn't very clearly explained by those log lines in an easily understandable way.

I initially started debugging this on Chrome OS, and without wiping your entire machine & putting it into developer mode (which I ended up doing in the end), you can't actually check what certificates & trusted CAs are being passed into the daemon, and the log to me read as if the CA certificate wasn't being placed in the trust store.

If you don't want to change it, that's fine, but as feedback, it would be helpful if it points it out specifically a little more.

[tobiasbrunner]

I appreciate you linking the FAQ - I wasn't able to find this at the time, even after searching for the relevant string & strongswan together on Google.

Yeah, kinda weird. In a Google search for "no trusted RSA public key found for" I tried now, the FAQs didn't show up at all. Only after disabling skipping duplicates on the last page did it show up (on page 3). (I guess since the FAQs list several error messages, the page might look like a duplicate of some of the logs Google did list.)

To be fair, we always ask people to check the FAQ as a first step (e.g. here, which is linked on the support page, or in #196).

If you don't want to change it, that's fine, but as feedback, it would be helpful if it points it out specifically a little more.

Changing that log message is tricky, as where it's logged we only know what it already states, i.e. that no trusted key was found for that identity. We don't know if there actually was a matching key/certificate but it couldn't be validated, or if that couldn't even be attempted because no matching certificate was found.

However, as a user you can differentiate these cases due to the absence of other log message. Because if a matching certificate was found, you'd see using certificate "...", using trusted ca certificate "..." etc. when there is an attempt to validate it. And you'd also get explicit log messages if the certificate has expired or the issuer certificate is missing. (I guess that could be added to the FAQ to clarify the checklist there.)