As far as I can tell, the logging process is as follows:
tcpdump>sed>logger>logger.log
The file ‘logger.log’ is then picked up by rsyslog, and entries transmitted to remote syslog server.
I captured a couple of records from ‘logger.log’
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
Jul 3 11:23:14 pfsense pf: 2012-07-03 11:21:52.403847 rule 86/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 818, offset 0, flags [none], proto UDP (17), length 521) 192.168.3.5.5060 > 81.x.x.203.61347: SIP, length: 493
From this, it is clear that multiple records exist for a single firewall event. The date/time slots and the header id are identical. The lines however, do not arrive at the remote syslog server in this precise sequence, so I cannot filter there for duplicate entries.
I think I have found part of the answer; after booting there are five(?) instances of tcpdump listening on pflog0. After making many changes to the firewall rules, I counted 34 instances. Each ‘reloading_filter’ results in an extra instance of tcpdump, sed and logger.
Regarding the amount of tcpdump, sed and logger processes started by a filter reload; that was my own stupid mistake. I made a small change in ‘/etc/inc/filter.inc’ to make the date/time of the packet visible (-tttt), and missed the line above that, that checked if such a process was already running (pgrep).
function filter_pflog_start() {
global $config, $g;
if(isset($config['system']['developerspew'])) {
$mt = microtime();
echo "filter_pflog_start() being called $mt\n";
}
mute_kernel_msgs();
$output = 0;
exec("/bin/pgrep -af 'tcpdump -s 256 -v -l -n -e -ttt -i pflog0'", $output, $retval);
if($retval != 0)
mwexec_bg("/usr/sbin/tcpdump -s 256 -v -l -n -e -tttt -i pflog0 | /usr/bin/sed -e 'N;s/\\n //;P;D;'| logger -t pf -p local0.info");
unmute_kernel_msgs();
}
But this does not account for the long delays between packet arrival and the time they are logged.
Any insights would be most welcome.