[kea-dev] Suggestions for DHCP packets logs

[Chaigneau, Nicolas]

> On 12/06/15 11:11, Chaigneau, Nicolas wrote:
> > The following are recommendations for implementing the logging of DHCP 
> > packets.
> >
> > These originate from functional requirements, and from performance 
> > tests I've run (on our implementation of packets logging, handled 
> > through a hook).
> > 
> > Discussion is welcome as always!
> Thanks for sharing those. I assume that your suggestions are addressed at some future packet logging implementation, not the current Kea code, right?


Yes. :)
More precisely, these are suggestions based on my experience using Kea 0.9.1 with custom hooks.
I'm focused on performances because I'm trying to get the most out of Kea, but I understand that flexibility is more important for the typical DHCP setup.


> 
> While we do have code for logging contents of each packet (including parsed options) in current Kea, it is on very high debugging level and is not intended to be used during normal operation. It is there just in case we need to debug an issue.
> 
> > 1) don't use log4cplus
> > 
> > There is a very significant performance penalty when logging a large 
> > volume of data through log4cplus.
> We intend to keep minimal amount of logging per packet in the default logging setup. Ideally that should be a single line for each incoming and outgoing packet.


That's what I did. But even a single line per packet, at a rate of thousands of packets received per second, amounts to roughly twice as many lines per second logged. That's a lot.


> 
> > Packets should not be logged through log4cplus. Packets should be 
> > written directly through a fstream. (I've measured about 30% 
> > improvement in DORA/s capacity, as compared to using log4cplus).
> We can possibly consider adding such a feature, but a single line for each packet will be logged through log4cplus, at least in the foreseeable future. log4cplus is takes care of all the logging
> destinations: file, syslog, stdout, stderr. That logging flexibility is something we think is very useful for users.


I understand.
As long as it can be switched off, and you're aware that there's a cost of doing so, that's ok.


> 
> We certainly can implement a dedicated mechanism for writing whole received packets. As Francis suggested, better name for it is packet dumping, rather than logging. It seems most convenient to dump them in pcap format, so anything that can handle wireshark of tcpdump output, could be used here. If you and other users find it useful, we may consider it implementing it some time after Kea 1.0.


Although I don't need this at the moment, I think that's an interesting idea.

Having the capture of a packet would be very useful to investigate potential issues in Kea. It would allow to replay a posteriori troublesome packets with Kea started in debug mode and see exactly what happens. Currently, there is no way to do that (other than looking at the logs and the code, and try and guess what was in the packet).

(granted, this far Kea seems very robust so I don't see that being useful on a daily basis.)

Also (obviously) it would allow to see exactly what is in the packet.
This would allow an external tool to collect information without being limited by what is in the log.
On the downside for such a tool, parsing would be much more complicated.

That said, even though a DHCP packet is small (300 octets or so ?), it could produce very big files if there's a lot of traffic.
So again I would recommend the possibility, for example, to have output files split on a time or size criteria.


> 
> > 2) enabling packets logs
> > 
> > A parameter should allow to enable or disable the packets logs.
> If we implement packet dumping, it will surely be disabled by default and there will be a parameter to enable it.
> 
> > 3) flushing of packets logs
> > 
> > There is also a performance benefit in allowing to disable explicit 
> > flushing (ie each time a line is logged) of the log file. In this 
> > case, automatic flushing is handled by the system and happens whenever 
> > the output buffer is full (or when the file is closed).
> I vaguely remember that there's flush parameter in log4cplus, but I can't seem to find any uses of it in the code. Apparently we don't touch flush switch and keep it in the default state, whatever it is.


Yeah there is such a parameter. Currently it's hard-coded in Kea.
I've tried to change it to see if it would improve performances. It does (see http://kea.isc.org/ticket/3752), but it was not sufficient for my needs.
 

> > This is not necessarily desirable for everyone. A parameter should be 
> > provided to control whether packets logs are flushed explicitly or 
> > automatically.
> No, but there are very good reasons why flush may be called. Imagine a server crash. You really want to every log entry before the crash. If they are not flushed, the data in buffers may be never logged when the signal comes.


That's true.
Personally I see that as an acceptable risk (logs are not critical, servers don't crash often). Other people might disagree. :)


> 
> But I agree that having the ability to disable flush is useful.
> 
> > 4) handle packets logs rotation
> > 
> > Rotation of the packets logs should not be delegated to an external 
> > task such as logrotate. This should be handled directly by Kea.
> We expose several log4cplus parameters that are dedicated to rotating logs, but I think we never tested this. See Kea User's guide, sections
> 13.1.2.2.1 (maxsize) that specifies maximum log file size and 13.1.2.2.2
> (maxver) that specifies number of old log files to keep around.


I tried to play with these with no success and gave up, but it was on an early 0.9 Kea version.
Maybe it works now, I'll have to check.


> 
> > A solution is to have Kea directly handle the file rotation. This can 
> > be done on several criteria, for instance: - on a time frame basis 
> > (eg. hourly packets log files), - when file size exceeds a given 
> > limit, - or a number of logged packets, ...
> Please see what we already have there (my comments above). If that's not sufficient, can you take a look at log4cplus and check whether there are features that are not exposed by Kea yet, but would solve your problem.
> If yes, we can add those parameters easily.


Well the primary issue for me is performances, so unless I find something that improves log4cplus on that matter, the other parameters become irrelevant.


> 
> If not, we'll have to think about implementing something. I must honestly admit that our schedules up to 1.0 are very tight, so any log4cplus replacement is out of question.


No problem at all, I understand.
As I said, these were only suggestions. I can do all I need with hooks.


> 
> Angelo mentioned google glog. I took at quick look at it. One major thing missing, as compared to log4cplus, is ability to have multiple destinations. IMHO this is a significant benefit of log4plus - you can have different levels and outputs configured for each logger. This ability to increase or decrease logging on per component basis is very useful when you want to debug an issue.


I'm not familiar with glog. It would have to be tested to see how it compares to log4cplus performance-wise within Kea.
Also, I've found another logger whose author claim to be much more efficient than glog:
(but it's also only a simple file logger)

http://www.codeproject.com/Articles/288827/g-log-An-efficient-asynchronous-logger-using-Cplus

Well... it's worth reading at least.
Maybe for Kea 2.0 ? :)




Regards,
Nicolas.

This message contains information that may be privileged or confidential and is the property of the Capgemini Group. It is intended only for the person to whom it is addressed. If you are not the intended recipient, you are not authorized to read, print, retain, copy, disseminate, distribute, or use this message or any part thereof. If you receive this message in error, please notify the sender immediately and delete all copies of this message.