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’

Code:

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).

Code:

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.

Investigating the firewall logs, I noticed that traffic seems to arrive at the log in bursts; checking the actual packet time confirmed that. At first I thought that this might happen because of the rsyslog and mysql delays and/or queues, but the ‘time arrived’ is not manipulated in that chain, so the delay occurs before that.

A sample of the log:

Code:

ID    Logged              Packet              Host              Actin   Intf Source             Dest                Packet data
23689 2012-06-28 16:13:36 2012-06-28 16:07:45 192.168.3.1 1/0 block fxp0 62.0.111.233 52102 x.x.x.x        444 2012-06-28 16:07:45.568042 rule 1/0(match): block in on fxp0: (tos 0x0, ttl 51, id 15211, offset 0, flags [DF], proto TCP (6), length 60)   62.0.111.233.52102 > x.x.x.x.444: [|tcp]
23690 2012-06-28 16:13:36 2012-06-28 16:07:48 192.168.3.1 1/0 block fxp0 62.0.111.233 52102 x.x.x.x        444 2012-06-28 16:07:48.556767 rule 1/0(match): block in on fxp0: (tos 0x0, ttl 51, id 15212, offset 0, flags [DF], proto TCP (6), length 60)   62.0.111.233.52102 > x.x.x.x.444: [|tcp]
23691 2012-06-28 16:13:36 2012-06-28 16:08:10 192.168.3.1 52/0 pass bfe0 192.168.3.2    123 176.34.228.173  123 2012-06-28 16:08:10.001682 rule 52/0(match): pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
23692 2012-06-28 16:13:36 2012-06-28 16:10:07 192.168.3.1 53/0 pass bfe0 192.168.3.5    123 65.55.21.21 123 2012-06-28 16:10:07.058944 rule 53/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 5240, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
23693 2012-06-28 16:13:36 2012-06-28 16:11:37 192.168.3.1 53/0: pass bfe0 192.168.3.5   7045 192.93.0.4 53 2012-06-28 16:11:37.756235 rule 53/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 8054, offset 0, flags [none], proto UDP (17), length 74)   192.168.3.5.7045 > 192.93.0.4.53: [|domain]
23694 2012-06-28 16:13:36 2012-06-28 16:11:37 192.168.3.1 53/0 pass bfe0 192.168.3.5  53210 85.17.39.77 53 2012-06-28 16:11:37.815314 rule 53/0(match): pass in on bfe0: (tos 0x0, ttl 128, id 8055, offset 0, flags [none], proto UDP (17), length 74)   192.168.3.5.53210 > 85.17.39.77.53: [|domain]

In this sample, the maximum delay is about 7 minutes, but it is not a fixed delay. Longest delay until now: 21 minutes

Further investigation reveals that, after sorting all packages on the package date/time slot, all packages arrive at the firewall log five times. I managed to get the package date/time by changing the filter (/etc/inc/filter.inc), replacing ‘–ttt’ by ‘–tttt’ at the tcpdump line.

Sample log output, sorted by package date/time:

Code:

39262 2012-06-28 18:29:08 2012-06-28 18:24:53 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 176.34.228.173 123 2012-06-28 18:24:53.099456 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
39263 2012-06-28 18:29:08 2012-06-28 18:24:53 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 176.34.228.173 123 2012-06-28 18:24:53.099456 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
39281 2012-06-28 18:29:08 2012-06-28 18:24:53 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 176.34.228.173 123 2012-06-28 18:24:53.099456 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
39292 2012-06-28 18:29:08 2012-06-28 18:24:53 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 176.34.228.173 123 2012-06-28 18:24:53.099456 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
39302 2012-06-28 18:29:08 2012-06-28 18:24:53 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 176.34.228.173 123 2012-06-28 18:24:53.099456 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 176.34.228.173.123: NTPv4, length 48
39264 2012-06-28 18:29:08 2012-06-28 18:25:07 192.168.3.1 53/0 pass bfe0 192.168.3.5 123 65.55.21.21 123 2012-06-28 18:25:07.541366 rule 53/0  pass in on bfe0: (tos 0x0, ttl 128, id 23986, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
39265 2012-06-28 18:29:08 2012-06-28 18:25:07 192.168.3.1 53/0 pass bfe0 192.168.3.5 123 65.55.21.21 123 2012-06-28 18:25:07.541366 rule 53/0  pass in on bfe0: (tos 0x0, ttl 128, id 23986, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
39282 2012-06-28 18:29:08 2012-06-28 18:25:07 192.168.3.1 53/0 pass bfe0 192.168.3.5 123 65.55.21.21 123 2012-06-28 18:25:07.541366 rule 53/0  pass in on bfe0: (tos 0x0, ttl 128, id 23986, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
39293 2012-06-28 18:29:08 2012-06-28 18:25:07 192.168.3.1 53/0 pass bfe0 192.168.3.5 123 65.55.21.21 123 2012-06-28 18:25:07.541366 rule 53/0  pass in on bfe0: (tos 0x0, ttl 128, id 23986, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
39303 2012-06-28 18:29:08 2012-06-28 18:25:07 192.168.3.1 53/0 pass bfe0 192.168.3.5 123 65.55.21.21 123 2012-06-28 18:25:07.541366 rule 53/0  pass in on bfe0: (tos 0x0, ttl 128, id 23986, offset 0, flags [none], proto UDP (17), length 76)   192.168.3.5.123 > 65.55.21.21.123: NTPv3, length 48
39266 2012-06-28 18:29:08 2012-06-28 18:25:35 192.168.3.1 1/0 block fxp0 88.134.160.13 48296 xx.xx.xx.xxx 1080 2012-06-28 18:25:35.325961 rule 1/0  block in on fxp0: (tos 0x0, ttl 245, id 32346, offset 0, flags [DF], proto TCP (6), length 40)   88.134.160.13.48296 >  xx.xx.xx.xxx.1080: [|tcp]
39267 2012-06-28 18:29:08 2012-06-28 18:25:35 192.168.3.1 1/0 block fxp0 88.134.160.13 48296 xx.xx.xx.xxx 1080 2012-06-28 18:25:35.325961 rule 1/0  block in on fxp0: (tos 0x0, ttl 245, id 32346, offset 0, flags [DF], proto TCP (6), length 40)   88.134.160.13.48296 >  xx.xx.xx.xxx.1080: [|tcp]
39283 2012-06-28 18:29:08 2012-06-28 18:25:35 192.168.3.1 1/0 block fxp0 88.134.160.13 48296 xx.xx.xx.xxx 1080 2012-06-28 18:25:35.325961 rule 1/0  block in on fxp0: (tos 0x0, ttl 245, id 32346, offset 0, flags [DF], proto TCP (6), length 40)   88.134.160.13.48296 >  xx.xx.xx.xxx.1080: [|tcp]
39294 2012-06-28 18:29:08 2012-06-28 18:25:35 192.168.3.1 1/0 block fxp0 88.134.160.13 48296 xx.xx.xx.xxx 1080 2012-06-28 18:25:35.325961 rule 1/0  block in on fxp0: (tos 0x0, ttl 245, id 32346, offset 0, flags [DF], proto TCP (6), length 40)   88.134.160.13.48296 >  xx.xx.xx.xxx.1080: [|tcp]
39304 2012-06-28 18:29:08 2012-06-28 18:25:35 192.168.3.1 1/0 block fxp0 88.134.160.13 48296 xx.xx.xx.xxx 1080 2012-06-28 18:25:35.325961 rule 1/0  block in on fxp0: (tos 0x0, ttl 245, id 32346, offset 0, flags [DF], proto TCP (6), length 40)   88.134.160.13.48296 >  xx.xx.xx.xxx.1080: [|tcp]
39268 2012-06-28 18:29:08 2012-06-28 18:26:25 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 178.18.85.13 123 2012-06-28 18:26:25.113117 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 178.18.85.13.123: NTPv4, length 48
39269 2012-06-28 18:29:08 2012-06-28 18:26:25 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 178.18.85.13 123 2012-06-28 18:26:25.113117 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 178.18.85.13.123: NTPv4, length 48
39284 2012-06-28 18:29:08 2012-06-28 18:26:25 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 178.18.85.13 123 2012-06-28 18:26:25.113117 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 178.18.85.13.123: NTPv4, length 48
39295 2012-06-28 18:29:08 2012-06-28 18:26:25 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 178.18.85.13 123 2012-06-28 18:26:25.113117 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 178.18.85.13.123: NTPv4, length 48
39305 2012-06-28 18:29:08 2012-06-28 18:26:25 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 178.18.85.13 123 2012-06-28 18:26:25.113117 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 178.18.85.13.123: NTPv4, length 48
39270 2012-06-28 18:29:08 2012-06-28 18:27:39 192.168.3.1 1/0 block fxp0 141.101.126.194 80 xx.xx.xx.xxx 3022 2012-06-28 18:27:39.887964 rule 1/0  block in on fxp0: (tos 0x0, ttl 56, id 0, offset 0, flags [DF], proto TCP (6), length 44)   141.101.126.194.80 >  xx.xx.xx.xxx.3022: [|tcp]
39272 2012-06-28 18:29:08 2012-06-28 18:27:39 192.168.3.1 1/0 block fxp0 141.101.126.194 80 xx.xx.xx.xxx 3022 2012-06-28 18:27:39.887964 rule 1/0  block in on fxp0: (tos 0x0, ttl 56, id 0, offset 0, flags [DF], proto TCP (6), length 44)   141.101.126.194.80 >  xx.xx.xx.xxx.3022: [|tcp]
39285 2012-06-28 18:29:08 2012-06-28 18:27:39 192.168.3.1 1/0 block fxp0 141.101.126.194 80 xx.xx.xx.xxx 3022 2012-06-28 18:27:39.887964 rule 1/0  block in on fxp0: (tos 0x0, ttl 56, id 0, offset 0, flags [DF], proto TCP (6), length 44)   141.101.126.194.80 >  xx.xx.xx.xxx.3022: [|tcp]
39296 2012-06-28 18:29:08 2012-06-28 18:27:39 192.168.3.1 1/0 block fxp0 141.101.126.194 80 xx.xx.xx.xxx 3022 2012-06-28 18:27:39.887964 rule 1/0  block in on fxp0: (tos 0x0, ttl 56, id 0, offset 0, flags [DF], proto TCP (6), length 44)   141.101.126.194.80 >  xx.xx.xx.xxx.3022: [|tcp]
39306 2012-06-28 18:29:08 2012-06-28 18:27:39 192.168.3.1 1/0 block fxp0 141.101.126.194 80 xx.xx.xx.xxx 3022 2012-06-28 18:27:39.887964 rule 1/0  block in on fxp0: (tos 0x0, ttl 56, id 0, offset 0, flags [DF], proto TCP (6), length 44)   141.101.126.194.80 >  xx.xx.xx.xxx.3022: [|tcp]
39271 2012-06-28 18:29:08 2012-06-28 18:27:55 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 80.85.129.25 123 2012-06-28 18:27:55.119211 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 80.85.129.25.123: NTPv4, length 48
39273 2012-06-28 18:29:08 2012-06-28 18:27:55 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 80.85.129.25 123 2012-06-28 18:27:55.119211 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 80.85.129.25.123: NTPv4, length 48
39286 2012-06-28 18:29:08 2012-06-28 18:27:55 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 80.85.129.25 123 2012-06-28 18:27:55.119211 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 80.85.129.25.123: NTPv4, length 48
39297 2012-06-28 18:29:08 2012-06-28 18:27:55 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 80.85.129.25 123 2012-06-28 18:27:55.119211 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 80.85.129.25.123: NTPv4, length 48
39307 2012-06-28 18:29:08 2012-06-28 18:27:55 192.168.3.1 52/0 pass bfe0 192.168.3.2 123 80.85.129.25 123 2012-06-28 18:27:55.119211 rule 52/0  pass in on bfe0: (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 76)   192.168.3.2.123 > 80.85.129.25.123: NTPv4, length 48
39274 2012-06-28 18:29:08 2012-06-28 18:28:57 192.168.3.1 1/0 block fxp0 218.213.224.34 5065 xx.xx.xx.xxx 5060 2012-06-28 18:28:57.833595 rule 1/0  block in on fxp0: (tos 0x0, ttl 52, id 0, offset 0, flags [DF], proto UDP (17), length 432)   218.213.224.34.5065 >  xx.xx.xx.xxx.5060: SIP, length: 404
39275 2012-06-28 18:29:08 2012-06-28 18:28:57 192.168.3.1 1/0 block fxp0 218.213.224.34 5065 xx.xx.xx.xxx 5060 2012-06-28 18:28:57.833595 rule 1/0  block in on fxp0: (tos 0x0, ttl 52, id 0, offset 0, flags [DF], proto UDP (17), length 432)   218.213.224.34.5065 >  xx.xx.xx.xxx.5060: SIP, length: 404
39287 2012-06-28 18:29:08 2012-06-28 18:28:57 192.168.3.1 1/0 block fxp0 218.213.224.34 5065 xx.xx.xx.xxx 5060 2012-06-28 18:28:57.833595 rule 1/0  block in on fxp0: (tos 0x0, ttl 52, id 0, offset 0, flags [DF], proto UDP (17), length 432)   218.213.224.34.5065 >  xx.xx.xx.xxx.5060: SIP, length: 404
39298 2012-06-28 18:29:08 2012-06-28 18:28:57 192.168.3.1 1/0 block fxp0 218.213.224.34 5065 xx.xx.xx.xxx 5060 2012-06-28 18:28:57.833595 rule 1/0  block in on fxp0: (tos 0x0, ttl 52, id 0, offset 0, flags [DF], proto UDP (17), length 432)   218.213.224.34.5065 >  xx.xx.xx.xxx.5060: SIP, length: 404
39308 2012-06-28 18:29:08 2012-06-28 18:28:57 192.168.3.1 1/0 block fxp0 218.213.224.34 5065 xx.xx.xx.xxx 5060 2012-06-28 18:28:57.833595 rule 1/0  block in on fxp0: (tos 0x0, ttl 52, id 0, offset 0, flags [DF], proto UDP (17), length 432)   218.213.224.34.5065 >  xx.xx.xx.xxx.5060: SIP, length: 404

What could be the cause of this?

I'm getting a few strange entries in my logs; the following lines (with the exception of the last line) arrived in my logs in the usual way (rsyslog>sql), but I also received an additional line as in the next table:

Additional lines:

Code:

#011(tos 0x0, ttl 190,id 36853, offset 0, flags [none], proto UDP (17), length 32)   80.x.x.x.30421 > 58.221.41.30.15474: UDP, length 0 #in log
#011(tos 0x0, ttl 163,id 64429, offset 0, flags [none], proto UDP (17), length 32)   80.x.x.x.33494 > 58.221.41.47.4263: UDP, length 0 #in log
#011(tos 0x0, ttl 24, id 50497, offset 0, flags [none], proto UDP (17), length 32)   80.x.x.x.47630 > 58.221.43.167.33524: UDP, length 0 #in log
#011(tos 0x0, ttl 1,  id 65264, offset 0, flags [none], proto UDP (17), length 32)   80.x.x.x.49298 > 184.71.237.114.7869: UDP, length 0 #NOT in log

Normal log:

Code:

2012-06-26 19:16 1/0(match): block: fxp0 (tos 0x0, ttl 113, id 2192, offset 0, flags [none], proto ICMP (1), length 60)   58.221.41.30 > 80.x.x.x: ICMP 58.221.41.30 udp port 15474 unreachable, length 40
2012-06-26 21:54 1/0(match): block: fxp0 (tos 0x0, ttl 113, id 3002, offset 0, flags [none], proto ICMP (1), length 60)   58.221.41.47 > 80.x.x.x: ICMP 58.221.41.47 udp port 4263 unreachable, length 40
2012-06-27 03:23 1/0(match): block: fxp0 (tos 0x0, ttl 114, id 12556, offset 0, flags [none], proto ICMP (1), length 60)   58.221.43.167 > 80.x.x.x: ICMP 58.221.43.167 udp port 33524 unreachable, length 40

The last line did not show up in my SQL database, perhaps because the ttl=1?

Any suggestions?

I just started using pfsense, and configured it to send log information to a remote server where the data is stored in a SQL database. Viewing those logs (or the firewall log on pfsense), all outbound requests to websites are visible, so the ‘source’ column shows all outbound requests made across the WAN interface, but the inbound return traffic from those Internet sites is not visible. I do understand that pfsense works as a NAT proxy for WAN traffic and that LAN sources never communicate directly with WAN sources, but I would like to see which WAN sources respond on a LAN request. As an example, when you visit: http://windows7forums.com, there are about 100 connections more visible in TCPVIEW, and none of those connections shows in the firewall logs.

Probably I missed a configuration setting, and perhaps someone is willing to help me with this.