How to read a IPSec-Log

Ruddimaster · Mar 31, 2015, 7:06 AM

Hello,

we have approx 40 VPN-Tunnels. Since upgrade to strongswan ist isn't possible to separate the log entires to its VPN-Tunnel.
With Racoon in each entry the vpn description was included.

At this point I can't use this log for troubleshooting.
Is there an option like firewall log (rule) to add a column or something else?

Dirk

Ruddimaster · Apr 1, 2015, 7:44 AM

I'm the only one with this problem?

doktornotor · Apr 1, 2015, 7:46 AM

No, you are not the only one. The logs are absolutely useless flood of junk even with loglevel dropped to absolute minimum. The upstream guys need a heavy hit with a cluebat.

neik · Apr 2, 2015, 6:04 PM

@Ruddimaster:

I'm the only one with this problem?

You are not the only one, but I know it certainly seems like it sometimes. The racoon logs were great, whereas the new logs are useless.

cmb · Apr 2, 2015, 6:18 PM

Our log display code showed the associated tunnel by the IP in racoon's logs. The challenge with strongswan's logs is it doesn't necessarily have the IP in relevant lines nor any other way of differentiating easily. There's a ticket or two open in this area to help things here in the future where we can.

jimp · Apr 2, 2015, 7:53 PM

In addition to the identification problem, for interpreting the messages we are slowly building a list of example logs and explanations/fixes here:

https://doc.pfsense.org/index.php/IPsec_Troubleshooting#Common_Errors_.28strongSwan.2C_pfSense_.3E.3D_2.2.x.29

As we find more good examples, they will be added to the wiki.

cmb · Apr 3, 2015, 4:15 AM

This will help significantly.
https://github.com/pfsense/pfsense/commit/db9e5154d64dfc537870b44f5b262ff940c0be70

I didn't realize it was only enabled for auth facility previously. That'll help greatly in writing a GUI log parser in the future, and at least the text has identifiers now.

Now you'll have logs like:

Apr  2 23:54:02 22vpntest charon: 14[NET] <con2|1> received packet: from 203.0.113.44[500] to 1.2.3.27[500] (96 bytes)
Apr  2 23:54:02 22vpntest charon: 14[ENC] <con2|1> parsed INFORMATIONAL response 2 [ ]
Apr  2 23:54:12 22vpntest charon: 14[NET] <con2|1> received packet: from 203.0.113.44[500] to 1.2.3.27[500] (96 bytes)
Apr  2 23:54:12 22vpntest charon: 14[ENC] <con2|1> parsed INFORMATIONAL request 5 [ ]
Apr  2 23:54:12 22vpntest charon: 14[ENC] <con2|1> generating INFORMATIONAL response 5 [ ]</con2|1></con2|1></con2|1></con2|1></con2|1>

for connection con2 as shown by 'ipsec statusall'. That'll be in the next 2.2.2 snapshots.

Ruddimaster · Apr 8, 2015, 8:13 AM

Hi cmb,

thanks for your reply. This will help to read the log extremely. In future it will be nice, it is possible to filter each tunnel. If you have approx 50 tunnells, there's a lot going on.

Ruddimaster · Apr 27, 2015, 7:23 AM

I have upgraded to 2.2.2 an I am still unable to read this log:

Apr 27 09:13:57 	charon: 15[ENC] <con17000|131734> parsed INFORMATIONAL_V1 request 395783956 [ HASH N(DPD_ACK) ]
Apr 27 09:13:57 	charon: 15[NET] <con17000|131734> received packet: from xxx.xxx.xxx.xxx[4500] to xxx.xxx.xxx.xxx[4500] (140 bytes)
Apr 27 09:13:57 	charon: 15[NET] <con17000|131734> sending packet: from xxx.xxx.xxx.xxx[4500] to xxx.xxx.xxx.xxx[4500] (140 bytes)
Apr 27 09:13:57 	charon: 15[ENC] <con17000|131734> generating INFORMATIONAL_V1 request 1846969741 [ HASH N(DPD) ]
Apr 27 09:13:57 	charon: 15[IKE] <con17000|131734> sending DPD request
Apr 27 09:13:57 	charon: 15[IKE] <con17000|131734> sending DPD request
Apr 27 09:13:56 	charon: 15[NET] <217862> sending packet: from xxx.xxx.xxx.xxx[500] to xxx.xxx.xxx.xxx[500] (56 bytes)
Apr 27 09:13:56 	charon: 15[ENC] <217862> generating INFORMATIONAL_V1 request 3646241847 [ N(NO_PROP) ]
Apr 27 09:13:56 	charon: 15[IKE] <217862> no proposal found
Apr 27 09:13:56 	charon: 15[IKE] <217862> no proposal found
Apr 27 09:13:56 	charon: 15[CFG] <217862> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536
Apr 27 09:13:56 	charon: 15[CFG] <217862> received proposals: IKE:AES_CBC_256/HMAC_MD5_96/PRF_HMAC_MD5/MODP_1536
Apr 27 09:13:56 	charon: 15[IKE] <217862> xxx.xxx.xxx.xxx is initiating a Main Mode IKE_SA
Apr 27 09:13:56 	charon: 15[IKE] <217862> xxx.xxx.xxx.xxx is initiating a Main Mode IKE_SA
Apr 27 09:13:56 	charon: 15[IKE] <217862> received DPD vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received DPD vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received XAuth vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received XAuth vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received Cisco Unity vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received Cisco Unity vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received strongSwan vendor ID
Apr 27 09:13:56 	charon: 15[IKE] <217862> received strongSwan vendor ID
Apr 27 09:13:56 	charon: 09[NET] <217861> sending packet: from xxx.xxx.xxx.xxx[500] to xxx.xxx.xxx.xxx[500] (56 bytes)
Apr 27 09:13:56 	charon: 09[ENC] <217861> generating INFORMATIONAL_V1 request 3135978726 [ N(NO_PROP) ]
Apr 27 09:13:56 	charon: 09[IKE] <217861> no proposal found
Apr 27 09:13:56 	charon: 09[IKE] <217861> no proposal found
Apr 27 09:13:56 	charon: 09[CFG] <217861> configured proposals: IKE:AES_CBC_256/HMAC_SHA1_96/PRF_HMAC_SHA1/MODP_1536
Apr 27 09:13:56 	charon: 09[CFG] <217861> received proposals: IKE:AES_CBC_256/HMAC_MD5_96/PRF_HMAC_MD5/MODP_1536
Apr 27 09:13:56 	charon: 09[IKE] <217861> xxx.xxx.xxx.xxx is initiating a Main Mode IKE_SA
Apr 27 09:13:56 	charon: 09[IKE] <217861> xxx.xxx.xxx.xxx is initiating a Main Mode IKE_SA
Apr 27 09:13:56 	charon: 09[IKE] <217861> received DPD vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received DPD vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received XAuth vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received XAuth vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received Cisco Unity vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received Cisco Unity vendor ID
Apr 27 09:13:56 	charon: 09[IKE] <217861> received strongSwan vendor ID</con17000|131734></con17000|131734></con17000|131734></con17000|131734></con17000|131734></con17000|131734>

Can anyone send me a hint, to separate each entry to its own tunnel?

cmb · Apr 27, 2015, 11:03 PM

@Ruddimaster:

Can anyone send me a hint, to separate each entry to its own tunnel?

The one that shows "con17000" matches with the tunnel that shows as con17000 in the output of "ipsec statusall". The ones with no con* log marker, rather <217862>, <217861>, are connection attempts that don't match any configured connection.

mrjohnbravo · Jan 25, 2017, 10:17 PM

The one that shows "con17000" matches with the tunnel that shows as con17000 in the output of "ipsec statusall". The ones with no con* log marker, rather <217862>, <217861>, are connection attempts that don't match any configured connection.

<rant>another case of dev's not using the software they write in a production environment.

This above reply is also entirely useless in the PFSense UI context as there is no reference in the GUI to the con number being referred to and so there is still no way to associate with an indvidual connection. And even when you go to ssh and run that command you get a non-static number for any given connection that may in fact change and will have a new and seemingly arbitrary con number. And last but not least… in the GUI in the LOG when your troubleshooting skimming literally thousands of useless chatty entries it's extremely difficult to actually see con1000 vs con3000 vs con30000 vs con10000
. I'd be willing to pay a bounty for the solution to this issue as it has made troubleshooting any but the most simplistic of configurations a real nightmare.</rant>

nc21 · Jan 3, 2018, 2:10 PM

Several years after these pertinent remarks, it is sad to see that nothing has been done to make the log display readable.
Happy new year anyway ;D