Netgate Discussion Forum
    • Categories
    • Recent
    • Tags
    • Popular
    • Users
    • Search
    • Register
    • Login

    Log delay

    Scheduled Pinned Locked Moved Firewalling
    2 Posts 1 Posters 1.5k Views
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • N Offline
      nebukadnezar
      last edited by

      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?

      1 Reply Last reply Reply Quote 0
      • N Offline
        nebukadnezar
        last edited by

        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.

        1 Reply Last reply Reply Quote 0
        • First post
          Last post
        Copyright 2025 Rubicon Communications LLC (Netgate). All rights reserved.