Bug #2626
closedPatch included: syslog.conf allows duplicate logging of daemon.info messages (e.g. from snort or dnsmasq)
100%
Description
Took me a while to hunt this down, and it's the same issue as reported in:
http://forum.pfsense.org/index.php?topic=46483.0
and
http://forum.pfsense.org/index.php/topic,30889.0.html
and
http://forum.pfsense.org/index.php/topic,18636.0.html
To find the problem, first I edited /etc/inc/system.inc to add the -vv option when starting syslogd:
@ -584,9 +584,9
@
// Are we logging to a least one remote server ?
if(strpos($syslogconf, "@") != false)
- $retval = mwexec_bg("/usr/sbin/syslogd c -c -l /var/dhcpd/var/run/log -f {$g['varetc_path']}/syslog.conf");
+ $retval = mwexec_bg("/usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f {$g['varetc_path']}/syslog.conf -vv");
else {
$retval = mwexec_bg("/usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f {$g['varetc_path']}/syslog.conf");
+ $retval = mwexec_bg("/usr/sbin/syslogd -c -c -l /var/dhcpd/var/run/log -f {$g['varetc_path']}/syslog.conf -vv");
}
} else {
Then restart syslogd by clicking 'apply' in the syslog settings page to make it pick up the new config. Now syslogd includes the facility and level with each message:
Sep 7 02:18:25 <daemon.notice> floe snort54230: Found pid path directive (/var/run)
Sep 7 02:18:25 <daemon.notice> floe snort54230: Found pid path directive (/var/run)
Sep 7 02:18:25 <daemon.notice> floe snort54230: Running in IDS mode
Sep 7 02:18:25 <daemon.notice> floe snort54230: Running in IDS mode
It seems the duplicate messages are daemon.notice. Examining /var/etc/syslog.conf for an explanation, it appears as though two distinct logging predicates will match daemon.notice, and both dump to system.log
*.notice;kern.debug;lpr.info;mail.crit
and
auth.info;authpriv.info;daemon.info
It looks like syslog.conf is generated by /etc/inc/system.inc, so that's where I tested a fix. The following patch fixes the double-logging problem for daemon.info messages by moving the daemon.info predicate for the system.log destination into the *.notice line.
[2.0.1-RELEASE][admin@floe.4952]/etc/inc(278): diff u system.inc.bk system.inc system.inc.bk 2012-09-07 02:47:17.000000000
--0700.notice;kern.debug;lpr.info;mail.crit; {$log_directive}{$g['varlog_path']}/system.log
++ system.inc 2012-09-07 03:00:04.000000000 -0700@ -539,11 +539,11
@
local3.* {$log_directive}{$g['varlog_path']}/vpn.log
local4.* {$log_directive}{$g['varlog_path']}/portalauth.log
local7.* {$log_directive}{$g['varlog_path']}/dhcpd.log
.notice;kern.debug;lpr.info;mail.crit;daemon.info {$log_directive}{$g['varlog_path']}/system.log
news.err;local0.none;local3.none;local4.none; {$log_directive}{$g['varlog_path']}/system.log
local7.none {$log_directive}{$g['varlog_path']}/system.log
security.* {$log_directive}{$g['varlog_path']}/system.log
-auth.info;authpriv.info;daemon.info {$log_directive}{$g['varlog_path']}/system.log
+auth.info;authpriv.info {$log_directive}{$g['varlog_path']}/system.log
auth.info;authpriv.info |exec /usr/local/sbin/sshlockout_pf 15
*.emerg *
Note that this may not apply for all possible configurations (e.g. I'm not using any remote syslog servers), but works for me.
Cheers,
-dre
Updated by Andre LaBranche over 12 years ago
Er... upon further consideration, I don't actually know what is going on. Snort emits daemon.notice, and dnsmasq emits daemon.info, and there is no daemon.* anywhere in the config, but both are not being double logged as they were before. I can't think of any good reason why this change seems to work, but maybe I'll come up with something... Or maybe something else is to blame.
Also, it appears that dnsmasq was logging normally before I installed Snort.
Updated by Andre LaBranche over 12 years ago
Haha, ok I had it right the first time. The key sentence from the syslog.conf man page is:
If a received message matches the specified facility and is of the specified level (or a higher level), the action specified in the action field will be taken.
'notice' is higher level than 'info', which means daemon.info matches messages from daemon of level emerg, alert, crit, err, warning, and notice. So, two different lines match all messages from daemon (except at 'debug' level), and both have the same action of logging to /var/log/system.log. So pretty much all daemon messages (except debug, which are not logged) will be duplicated in this config. I'm still not sure why it appears that dnsmasq logged normally prior to installing snort, since I can't find any evidence of snort trying to change the syslog config.
Updated by Renato Botelho almost 12 years ago
- Status changed from New to Feedback
- % Done changed from 80 to 100
Applied in changeset 2ba3ea05709b63127bc2f7856635292f7bc10623.
Updated by Renato Botelho almost 12 years ago
- Status changed from Feedback to Resolved
Updated by Andre LaBranche over 11 years ago
Just updated to 2.0.3; this problem is still here (or came back), with the same cause as before. In my installed copy of /etc/inc/system.inc, I see two different config lines matching messages from daemon at greater than or equal to 'notice’ severity, and sending them to system.log.
The “*.notice” portion of /etc/inc/system.inc:544:
*.notice;kern.debug;lpr.info;mail.crit; {$log_directive}{$g['varlog_path']}/system.log
The “daemon.info” portion of /etc/inc/system.inc:548
auth.info;authpriv.info;daemon.info {$log_directive}{$g['varlog_path']}/system.log
To demonstrate the undesired double-logging of messages from daemon >= notice, first we'll make a small function to do some test logging from 'daemon' at a specified severity level.
[2.0.3-RELEASE][root@floe.cmpd]/(120): sh # logAtLevel () { > date > logger + > logger -p daemon.$1 ${1}bang > logger _ > clog /var/log/system.log | tail -n 4 > date > }
Next we'll run the function with log levels info, notice, and warn.
# logAtLevel info Sat Jun 29 03:18:00 PDT 2013 Jun 29 03:15:40 floe miniupnpd[15009]: unsupported NAT-PMP version : 2 Jun 29 03:18:00 floe root: + Jun 29 03:18:00 floe root: infobang Jun 29 03:18:00 floe root: _ Sat Jun 29 03:18:00 PDT 2013 # # logAtLevel notice Sat Jun 29 03:18:16 PDT 2013 Jun 29 03:18:16 floe root: + Jun 29 03:18:16 floe root: noticebang Jun 29 03:18:16 floe root: noticebang Jun 29 03:18:16 floe root: _ Sat Jun 29 03:18:16 PDT 2013 # # logAtLevel crit Sat Jun 29 03:18:25 PDT 2013 Jun 29 03:18:25 floe root: + Jun 29 03:18:25 floe root: critbang Jun 29 03:18:25 floe root: critbang Jun 29 03:18:25 floe root: _ Sat Jun 29 03:18:26 PDT 2013
The messages with severity ‘notice’ and ‘crit’ were logged twice due to this logging (mis)configuration.
I’m guessing 2.0.3’s copy of /etc/inc/system.inc is different from trunk's, as the line numbers look different. This issue also exists in trunk.
https://github.com/pfsense/pfsense/blob/master/etc/inc/system.inc#L716
and
https://github.com/pfsense/pfsense/blob/master/etc/inc/system.inc#L720
also:
https://github.com/pfsense/pfsense/blob/master/etc/inc/system.inc#L734
and
https://github.com/pfsense/pfsense/blob/master/etc/inc/system.inc#L737
I’m not comfortable submitting a patch without spending some time reviewing the entire logging configuration, and the intentions behind this code. If you’d like me to do that, I’m willing. Thanks!
Updated by Renato Botelho over 11 years ago
It was changed only on 2.1, not 2.0.x, because of this you still see the issue on 2.0.3. You can apply the change on your systems manually if you need it on 2.0.x.