Scribe DHCP Message Log

[ScottW]

I have Scribe installed with a variety of filters, working great. I would like to have a separate log of DHCP messages available in the Scribe web-ui page, without affecting the dnsmaq.log file itself.

I run diversion, which sets dnsmasq to log directly to /opt/var/log/dnsmasq.log.
Can I create a "source" in syslog-ng.conf using ' source dnsmasq { file("/opt/var/log/dnsmasq.log") }; ' to get the dnsmasq messages to sent to syslog-ng?

Assuming that works, then will the code below put all DHCP messages in one file, and ignore the rest of the dnsmasq messages? Do I need the /dev/null destination, or can I ignore them by just having a filter and not specifying a destination?

Will syslog-ng "watching" /opt/var/log/dnsmasq.log as a "source" cause any issues when diversion needs to rotate the dnsmasq logs?

# grab dhcp messages from dnsmasq and log them

destination d_dhcp { file("/opt/var/log/dhcp.log"); };

destination d_oblivion { file("/dev/null"); };

filter f_dnsmasq-dhcp { ( program("dnsmasq-dhcp") ) };

filter f_dnsmasq_other { ( program("dnsmasq" ) ) };

log { source(dnsmasq); filter(f_dhcp); destination(d_dhcp); flags(final); };

log { source(dnsmasq); filter(f_dnsmasq_other); destination(d_oblivion); flags(final); };

#eof

 

[elorimer]

Undiscovered country and therefore somewhat dangerous, because you are picking up both dnsmasq and diversion in ways they may not be designed for. dnsmasq.log is really active. I can see three approaches.

The first, as you say, is to treat /opt/var/log/dsnmasq.log as a file source, extract what you want, and write it to a new file. I think syslog-ng will check to see if the file has changed, and if it has, opens it for reading the lines. I don't know what happens if dnsmasq wants to open it to write at the same time syslog-ng wants to read it, and whether and whether that stops dnsmasq until it can write. There seems to be an asyncronous option that might help if that is a problem.

I looked at my dnsmasq.log files and actually couldn't find any lines that didn't have dnsmasq as a program. If I follow what you want to do, then you will be discarding every line and have nothing to write to your new log. Before you start, do you see the same?

You don't need a null destination; just leave out the destination and syslog-ng will discard the messages. But since most everything will be discarded, you should have the discard logging statement first. If you do, then syslog-ng will discard most of the messages and stop processing them before processing what is left. Reverse it, and syslog will process most of the messages twice, unnecessarily.

The second would be to mess with diversion and change /etc/dnsmasq.conf to log to whatever will be your source file. Then, in your logging statements, include a first logging statement, without the final flag, that writes every message to /opt/var/log/dnsmasq.log, then goes on to do whatever you want. I think then diversion may do its stats, rotating, etc. in its normal way. The downside of this would be that diversion's self-healing properties are so extensive that it may fix it back without you knowing it.

The third would be to change /etc/dnsmasq.conf to enable logging but not specify a file. That would send the log statements to the normal logging channel, and you could filter the stream that way, writing everything to dnsmasq.log without the final flag and then again filtered as you want. Again the self-healing part.

 

[ScottW]

Thanks for all the analysis @elorimer, it is really helpful!

The first, as you say, is to treat /opt/var/log/dsnmasq.log as a file source, extract what you want, and write it to a new file. I think syslog-ng will check to see if the file has changed, and if it has, opens it for reading the lines. I don't know what happens if dnsmasq wants to open it to write at the same time syslog-ng wants to read it, and whether and whether that stops dnsmasq until it can write. There seems to be an asyncronous option that might help if that is a problem.

I share the concern... Both with frequency of writes to dnsmasq.log and the process diversion uses to rotate the files. I don't want some file contention to break lookups, logging, or diversion.

I just checked, and it appears dnsmasq is already invoked with the --log-async option, so hopefully that would avoid the write contention.

I looked at my dnsmasq.log files and actually couldn't find any lines that didn't have dnsmasq as a program. If I follow what you want to do, then you will be discarding every line and have nothing to write to your new log. Before you start, do you see the same?

If DHCP Logging is enabled, dnsmasq also writes DHCP messages (discover, request, ack, and so forth) to dnsmasq.log, with program name "dnsmasq-dhcp". An example:

Feb  2 08:41:31 dnsmasq-dhcp[19972]: DHCPDISCOVER(br0) 9c:8e:cd:1e:09:f7
Feb  2 08:41:31 dnsmasq-dhcp[19972]: DHCPOFFER(br0) 192.168.1.208 9c:8e:cd:1e:09:f7
Feb  2 08:41:31 dnsmasq-dhcp[19972]: DHCPREQUEST(br0) 192.168.1.208 9c:8e:cd:1e:09:f7
Feb  2 08:41:31 dnsmasq-dhcp[19972]: DHCPACK(br0) 192.168.1.208 9c:8e:cd:1e:09:f7 C8-SPARE

But since most everything will be discarded, you should have the discard logging statement first. If you do, then syslog-ng will discard most of the messages and stop processing them before processing what is left. Reverse it, and syslog will process most of the messages twice, unnecessarily.

Ah, yes -- much more efficient. Thanks!

The second would be to mess with diversion and change /etc/dnsmasq.conf to log to whatever will be your source file. Then, in your logging statements, include a first logging statement, without the final flag, that writes every message to /opt/var/log/dnsmasq.log, then goes on to do whatever you want. I think then diversion may do its stats, rotating, etc. in its normal way. The downside of this would be that diversion's self-healing properties are so extensive that it may fix it back without you knowing it.

The third would be to change /etc/dnsmasq.conf to enable logging but not specify a file. That would send the log statements to the normal logging channel, and you could filter the stream that way, writing everything to dnsmasq.log without the final flag and then again filtered as you want. Again the self-healing part.

I wanted to stay away from anything that would require changes to diversion's code or get in diversion's way, since there are frequent updates and lots of resiliency (the self-healing stuff you mention). Was hoping the syslog-ng "source{ file() }" would be transparent, but maybe not.

My biggest concern is with diversion's log rotation process, since it would be renaming dnsmasq.log while syslog-ng was watching/reading it. I will do some additional google-ing on the syslog-ng "source { file() } " operation to see if I can find any reports of how it reacts to file renaming.

I may just end up having to try it and see what breaks.

Thanks for the help!

 

[ScottW]

Just found this in the syslog-ng documentation, regarding using text files as source:

The syslog-ng application notices if a file is renamed or replaced with a new file, so it can correctly follow the file even if logrotation is used. When syslog-ng is restarted, it records the position of the last sent log message in the /opt/syslog-ng/var/syslog-ng.persist file, and continues to send messages from this position after the restart.

So, it sounds like the log rotation, which was my main concern, shouldn't cause a problem. There is also a "follow-freq()" option to set how frequently syslog-ng checks the file, which should add some efficiency by preventing it looking at the file every single time dnsmasq writes to it.

I'll give it all a try and see what happens.

 

[elorimer]

Just found this in the syslog-ng documentation, regarding using text files as source:


So, it sounds like the log rotation, which was my main concern, shouldn't cause a problem. There is also a "follow-freq()" option to set how frequently syslog-ng checks the file, which should add some efficiency by preventing it looking at the file every single time dnsmasq writes to it.

I'll give it all a try and see what happens.

Yes, syslog-ng follows the renamed file, which is why it is undisturbed after a logrotate, except for the restart.

Watch out for the follow-freq() flag, which I think may hold the file open and do the opposite of what you intend, if I understand this cryptic statement:

When using syslog-ng to read messages from the /proc/kmsg file, syslog-ng automatically disables the follow-freq() parameter to avoid blocking the file.

 

[elorimer]

I just checked, and it appears dnsmasq is already invoked with the --log-async option, so hopefully that would avoid the write contention.

Ah. Perhaps though this doesn't necessarily deal with contention over the file, but whether dnsmasq continues on its merry way without waiting for the log statement to be written. When dnsmasq has the opportunity to write, it may hold the file open longer writing the 5 to 100 messages queued. Will be interesting to see.

 

[dave14305]

I would think it’s really a matter of forcing dnsmasq to send all its logging to syslog (e.g. remove log-facility after Diversion adds it, or set it to “daemon” instead of the file path) and then have syslog-ng send the DNS messages to /opt/var/log/dnsmasq.log where Diversion would not know the difference. Maybe easier said than done since Diversion is foolproof and omniscient and might detect such hijinks.

 

[ScottW]

Thanks for all the additional comments!

What I have now seems to be working so far. I now have a separate dhcp.log in /opt/var/logs, and in the scribe web-ui addtion.

I tried the source{file()} definition with and without "follow-freq(2)". This made no discernable difference in operation. In both cases, I watched a "tail -f" of dnsmasq.log and didn't see any hesitations. Also, I saw no differences in cpu% or mem% used by syslog-ng or dnsmasq with either setting.

I manually ran diversion's "rotate-logs.div" script. The dnsmasq logs were rotated, dnsmasq continued normally, and syslog-ng continued normally. So, that seems to work -- but I will keep an eye on it.

In all, there were three steps to getting this setup.

(1) Turned off the "Hide DHCP/RA queries" option on the "LAN, DHCP Server" tab of the router GUI.

(2) Added a "dhcp" file to /opt/etc/syslog-ng.d:

# grab dhcp messages from dnsmasq and log them

source dnsmasq {
   file("/opt/var/log/dnsmasq.log" flags(no-hostname) ); 
};

destination d_dhcp { 
   file("/opt/var/log/dhcp.log");
};

filter f_dnsmasq-dhcp {
   ( program("dnsmasq-dhcp") )
};

filter f_dnsmasq_other {
   ( program("dnsmasq$") )   #Regex $ anchor to prevent matching "dnsmasq-dhcp"
};

# toss the non-dhcp messages first (no destination)
log {
   source(dnsmasq);
   filter(f_dnsmasq_other);
   flags(final);
};

# filter dhcp messages and write to dhcp.log
log {
   source(dnsmasq);
   filter(f_dnsmasq-dhcp);
   destination(d_dhcp);
   flags(final);
};

#eof

(3) Added a "dhcp" file to /opt/etc/logrotate.d to rotate the new dhcp.log file

I'll keep watching for any problems and report back if anything fails, but so far it appears to be working as intended. Thanks again for the assistance!

 

[elorimer]

Two suggestions about your step 2. I think it might be missing the beginning of the line? Also, as a matter of style I think the definition is better in your dhcp file. That way to undo everything you can just move/delete the file.

I see what you did in step 1; I have that turned on, which is why my logs didn't have anything.

I'm a little curious if the dhcp log has anything out of order. If so, perhaps you can add the extra logging in dnsmasq and maybe then automatically group by the resulting serial numbers.

 

[ScottW]

I think it might be missing the beginning of the line?

Correct, for my post I copy/pasted just the "file" line and neglected to capture the rest of the "source" statement from adjoining lines. (Previous post has been updated to show entire statement.)

Also, as a matter of style I think the definition is better in your dhcp file. That way to undo everything you can just move/delete the file.

Doh! I just assumed it had to be in syslog-conf because I wasn't thinking about how the @include works. I agree, it makes way more sense to have it in the /opt/etc/syslog-ng.d/dhcp file since that is the only place it is used. I made that change, and it is all working great. (Previous post has been updated,

I'm a little curious if the dhcp log has anything out of order. If so, perhaps you can add the extra logging in dnsmasq and maybe then automatically group by the resulting serial numbers.

It has only been capturing for a little over an hour, so just has renew sequences (DHCPREQUEST/DHCPACK) for about a dozen devices thus far. All those are in correct order. But I'll take a look in a day or two, after there has been more activity, including some DISCOVER actions.
[UPDATE 2022-02-05: After watching a couple days, I'm happy to report everything is being posted to the dhcp.log file in correct order, even during large volume periods were a dozen or more devices all initiate renewal near-simultaneously.]

Thanks for the help!