Project

General

Profile

Actions
Copy link

Bug #2626

closed

Patch included: syslog.conf allows duplicate logging of daemon.info messages (e.g. from snort or dnsmasq)

Added by Andre LaBranche about 12 years ago. Updated over 11 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Renato Botelho
Category:
Logging
Target version:
2.1
Start date:
09/07/2012
Due date:
% Done:

100%

Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
2.0.1
Affected Architecture:

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][]/etc/inc(278): diff u system.inc.bk system.inc
-- system.inc.bk 2012-09-07 02:47:17.000000000 0700
++ 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; {$log_directive}{$g['varlog_path']}/system.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

Actions
Copy link
 #1

Updated by Andre LaBranche about 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.

Actions
Copy link
 #2

Updated by Andre LaBranche about 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.

Actions
Copy link
 #3

Updated by Renato Botelho almost 12 years ago

  • Status changed from New to Feedback
  • % Done changed from 80 to 100
Actions
Copy link
 #4

Updated by Renato Botelho almost 12 years ago

  • Assignee set to Renato Botelho
Actions
Copy link
 #5

Updated by Renato Botelho almost 12 years ago

  • Status changed from Feedback to Resolved
Actions
Copy link
 #6

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!

Actions
Copy link
 #7

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.

Actions
Copy link

Also available in: Atom PDF