Log delay
-
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:
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:
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: 404What could be the cause of this?
-
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: 493From 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.
Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.