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: 404
What 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: 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.