Project

General

Profile

Issue #574

NAT Keep Alive message

Added by Manoj Kolakur almost 7 years ago. Updated over 4 years ago.

Status:
Closed
Priority:
Normal
Category:
-
Affected version:
5.0.1
Resolution:
No feedback

Description

Strongswan when kept behind NAT network a keep alive messages are sent, and are visible by capturing using tcpdump. Is logging support is available for these NAT Keep alive messages, if so What is the logging level to be set to see these messages.

bus-vlog.patch (1.53 KB) bus-vlog.patch Tobias Brunner, 22.09.2016 14:25

Associated revisions

Revision dac15e03 (diff)
Added by Tobias Brunner over 4 years ago

bus: Fix maximum log levels when mixing log/vlog implementing loggers

The maximum would not get set correctly when a logger is removed and the
first remaining logger in the list (the one with the highest log level) does
e.g. only implement vlog() while there are other loggers that implement log().
This would result in only max_vlevel getting set correctly while max_level
would incorrectly get set to -1 so that log() would not get called for any
of the loggers anymore.

References #574.

History

#1 Updated by Tobias Brunner almost 7 years ago

  • Status changed from New to Feedback
  • Assignee set to Tobias Brunner

Is logging support is available for these NAT Keep alive messages, if so What is the logging level to be set to see these messages.

A message is logged with log level 1 for the IKE subsystem (see LoggerConfiguration). In older releases the message simply was sending keep alive, since 5.0.1 it includes the target IP address and port (e.g. sending keep alive to x.x.x.x[4500]). Another message is logged for every packet sent by the socket-default plugin for the NET subsystem on level 2 (with a message like sending packet: from x.x.x.x[4500] to x.x.x.x[4500]).

#2 Updated by Manoj Kolakur almost 7 years ago

Thanks Tobias for the response.

We did this test again and found No Logging for NAT Keep Alive, we are seeing only logging for DPD Keep Alive.
Below is the TCP Dump capture where both DPD KA and NAT KA present.DPD KA got response from Gateway.

00:15:43.091382 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 1
00:16:03.091513 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 1
00:16:23.091645 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 1
00:16:33.378109 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 120
00:16:33.413144 IP 10.201.2.102.4500 > 192.168.1.2.4500: UDP, length: 64
00:16:53.091887 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 1
00:17:13.092022 IP 192.168.1.2.4500 > 10.201.2.102.4500: UDP, length: 1

Below is logging captured where only DPD KA messages present not NAT KA messages.

19700101 000633.377625 10 daemon.info charon: 13[ENC] generating INFORMATIONAL request 5 [ N(NATD_S_IP) N(NATD_D_IP) ]
19700101 000633.377641 10 daemon.info charon: 13[NET] sending packet: from 192.168.1.24500 to 10.201.2.1024500 (116 bytes)
19700101 000633.419694 10 daemon.info charon: 12[NET] received packet: from 10.201.2.1024500 to 192.168.1.24500 (60 bytes)
19700101 000633.419709 10 daemon.info charon: 12[ENC] parsed INFORMATIONAL response 5 [ ]
19700101 000953.377762 10 daemon.info charon: 12[ENC] generating INFORMATIONAL request 6 [ N(NATD_S_IP) N(NATD_D_IP) ]
19700101 000953.377791 10 daemon.info charon: 12[NET] sending packet: from 192.168.1.24500 to 10.201.2.1024500 (116 bytes)
19700101 000953.414205 10 daemon.info charon: 15[NET] received packet: from 10.201.2.1024500 to 192.168.1.24500 (60 bytes)
19700101 000953.414221 10 daemon.info charon: 15[ENC] parsed INFORMATIONAL response 6 [ ]

#3 Updated by Tobias Brunner over 6 years ago

How is the logging configured in your ipsec.conf, and strongswan.conf files, respectively? It looks like you disabled the logging for the IKE subsystem. Because before initiating a DPD exchange you should see sending DPD request in the log (logged on level 1 in the IKE subsystem, just like the NAT keep alive message).

#4 Updated by Manoj Kolakur over 6 years ago

The logging configuration is as shown below:
charondebug="ike 4, chd 4, cfg 2, net 4, enc 2, lib 4, mgr 4, knl -1 dmn -1"

It is showing "sending DPD request" for the DPD KA messages(have not pasted in the logs above) , but i dont see any such log message for NAT KA messages.

#5 Updated by Tobias Brunner over 6 years ago

It is showing "sending DPD request" for the DPD KA messages(have not pasted in the logs above) , but i dont see any such log message for NAT KA messages.

Both messages are logged with the same log level, so you should see both. Did you check if your source code actually contains the log call (source:src/libcharon/sa/ike_sa.c#L485)?

#6 Updated by Manoj Kolakur over 6 years ago

Yes.. I have the log in the source code, but i don't see it appear in the logs..
There is no difference in this code and my code. my code is 5.1.0 version

#7 Updated by Tobias Brunner over 6 years ago

Since keep-alives are only sent if no other outbound traffic (that includes the DPD exchanges) occurred in the keep-alive interval (20s by default), it's definitely possible that you don't see a message in the log. But you wouldn't see any packets in tcpdump either. How did you configure dpddelay? Have you changed charon.keep_alive in strongswan.conf?

If you really see an outbound keep-alive packet in tcpdump, and at the same time, see no message in the log that's odd. Perhaps your syslog daemon is filtering some messages? Did you try starting the daemon with ipsec start --nofork, so that it logs to stderr?

#8 Updated by Jonathan Davies about 6 years ago

Tobias Brunner wrote:

Since keep-alives are only sent if no other outbound traffic (that includes the DPD exchanges) occurred in the keep-alive interval (20s by default),

I've noticed that this "keep alive" message doesn't get logged when my road-warriors and VPN server send logs to a syslog server (that's behind the my VPN server). I first thought that charon had stopped working at first.

#9 Updated by Martin Willi about 6 years ago

As we don't handle that log message any different than others, I don't think this is directly related to strongSwan.

Most likely your syslogger collects these messages to print one of those last log message appeared x times messages?

I'd recommend to directly log to a file using filelog to see if there are any differences.

Regards
Martin

#10 Updated by Tobias Brunner over 5 years ago

  • Status changed from Feedback to Closed
  • Resolution set to No feedback

#11 Updated by Emeric Poupon over 4 years ago

Hello,

I have the same behavior too, on strongSwan 5.4.0
The keep alive messages are actually sent: I see them using tcpdump and I see them in the remote charon log.

Not sure, but the code of the keep alive job looks like quite different from the DPD job: the ike sa is not checkout. Maybe that prevents the log to be printed?

Emeric

#12 Updated by Tobias Brunner over 4 years ago

I see them in the remote charon log

How so? These should never reach the daemon but just get consumed by the OS kernel (or is that not the case on FreeBSD?).

Not sure, but the code of the keep alive job looks like quite different from the DPD job: the ike sa is not checkout. Maybe that prevents the log to be printed?

What do you mean? The first thing the job does in execute() is checking out the IKE_SA.

#13 Updated by Emeric Poupon over 4 years ago

How so? These should never reach the daemon but just get consumed by the OS kernel (or is that not the case on FreeBSD?).

Here is a sample:

...
Sep 21 14:25:42 07[NET] received packet => 1 bytes @ 0x00007fffdf3f55d0
Sep 21 14:25:42 07[NET] received packet: from 172.16.1.252[45594] to 222.192.173.222[4500]
Sep 21 14:26:02 07[NET] received packet => 1 bytes @ 0x00007fffdf3f55d0
Sep 21 14:26:02 07[NET] received packet: from 172.16.1.252[45594] to 222.192.173.222[4500]
...

Not sure, but the code of the keep alive job looks like quite different from the DPD job: the ike sa is not checkout. Maybe that prevents the log to be printed?

What do you mean? The first thing the job does in execute() is checking out the IKE_SA.

Yes my bad: it does checkout it.

#14 Updated by Tobias Brunner over 4 years ago

How so? These should never reach the daemon but just get consumed by the OS kernel (or is that not the case on FreeBSD?).

Here is a sample:
[...]

I see. Must be some FreeBSD thing, the Linux kernel does not pass these to the userland.

Not sure, but the code of the keep alive job looks like quite different from the DPD job: the ike sa is not checkout. Maybe that prevents the log to be printed?

What do you mean? The first thing the job does in execute() is checking out the IKE_SA.

Yes my bad: it does checkout it.

Did you try what Martin proposed (i.e. adding additional custom log messages)?

#15 Updated by Emeric Poupon over 4 years ago

Did you try what Martin proposed (i.e. adding additional custom log messages)?

This is the strange part: I am using a file logger, and there is no way for me to see a log that is related to these keep alives.
I tried to add some logs with various levels and categories in several places:
- before each call of ike_sa->send_keepalive
- inside the send_keepalive function
- before/inside the keep alive job creation

=> nothing gets logged.

I tried to change the 0xFF packet that is sent, I do see the change using tcpdump though.

What do you think?

#16 Updated by Tobias Brunner over 4 years ago

Did you try what Martin proposed (i.e. adding additional custom log messages)?

This is the strange part: I am using a file logger, and there is no way for me to see a log that is related to these keep alives.
I tried to add some logs with various levels and categories in several places:
- before each call of ike_sa->send_keepalive
- inside the send_keepalive function
- before/inside the keep alive job creation

=> nothing gets logged.

I don't see any reason for that (actually, in ikev2/nat-rw/venus.daemon.log you can see the message). Are any other level 1 log messages for the ike subsystem logged? If you set the log level for net to 2 do you see a message when the packet is actually sent? What about messages in the job or mgr subsystems if you increase those to 2?

#17 Updated by Emeric Poupon over 4 years ago

Ok I have some more news.

I have a file logger set like that:

filelog {
/tmp/charon.debug {
time_format="%b %e %T"
ike_name=yes
append=yes
default=3
flush_line=yes
} #/tmp/charon.debug
} #filelog

I added some custom debug traces in the vlog method and around the max level settings: with the "ipsec" command I observe a lot of weird max levels changes during my tests.
Example: using "ipsec up" change all the max levels to -1 once the tunnel is UP, and no more logs seem to be written (including the keep alive ones).

It seems to be OK as long as I don't use any ipsec command.

Is the unregister_logger function the culprit?

#18 Updated by Tobias Brunner over 4 years ago

Example: using "ipsec up" change all the max levels to -1 once the tunnel is UP, and no more logs seem to be written (including the keep alive ones).

ipsec up (via stroke plugin and controller_t) registers a temporary logger that either has the level for all subsystems set to 4 (or -1 if ipsec stroke up-nb is used). This logger is automatically removed once the command finishes. This should leave the bus in a valid state, though (max_level should only be set to -1 if there are no loggers registered for a subsystem).

It seems to be OK as long as I don't use any ipsec command.

I can't reproduce that here.

Is the unregister_logger function the culprit?

There is definitely a bug there. Loggers are free to implement either log() or vlog() or both. But the code does currently not correctly set the maximum level if the remaining logger with the highest level only implements one of the methods (do you use charon-systemd? That's the only one that currently implements vlog()).

#19 Updated by Emeric Poupon over 4 years ago

There is definitely a bug there. Loggers are free to implement either log() or vlog() or both. But the code does currently not correctly set the maximum level if the remaining logger with the highest level only implements one of the methods (do you use charon-systemd? That's the only one that currently implements vlog()).

Thanks for pointing this out.
Actually we have made a custom logger plugin, implementing only log; indeed that seems to be the problem here.

#20 Updated by Tobias Brunner over 4 years ago

There is definitely a bug there. Loggers are free to implement either log() or vlog() or both. But the code does currently not correctly set the maximum level if the remaining logger with the highest level only implements one of the methods (do you use charon-systemd? That's the only one that currently implements vlog()).

Thanks for pointing this out.
Actually we have made a custom logger plugin, implementing only log; indeed that seems to be the problem here.

Did you mean vlog()? Because if all the loggers only implement log() there shouldn't be a problem. Anyway, the attached patch should fix the maximum levels.

#21 Updated by Emeric Poupon over 4 years ago

Did you mean vlog()? Because if all the loggers only implement log() there shouldn't be a problem. Anyway, the attached patch should fix the maximum levels.

Yes my bad.
Thanks for your patch, it fixed the problem!

#22 Updated by Tobias Brunner over 4 years ago

Thanks for your patch, it fixed the problem!

OK, I'll line that up for the next release.

Also available in: Atom PDF