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.


Locked