Mismatched Firewall Rules & Logs
-
Firewall logs ‘Act’ indicates rules that do not reflect the port logged.
For example the ‘Act’ for a log entry to destination port 25 indicates a telnet port and rule.
Firewall Log:
The rule that triggered this action is:@91 block drop in log quick on bfe0_vlan98 reply-to [bfe0_vlan <gateway ip="" address="">] inet proto tcp from any to <pfsense wan="" ip="" address="">port = telnet label “USER_RULE: Telnet”
Sep 30 19:30:05 WAN 117.21.220.5:2590 <pfsense wan="" ip="" address="">:25 TCP:S
Firewall Rules:
. . .
IPv4 TCP * * WAN address 23 (Telnet) * none Telnet
IPv4 TCP * * WAN address 25 (SMTP) * none MTA (SMTP MX)
. . .</pfsense></pfsense></gateway> -
Not sure why but now the rules and log 'Act' are in sync.
-
Something may have changed the ruleset numbers between the time the logs were generated and the time you checked. The rule numbers are logged as they happen, and if something changes there, they'll fail to line up from that point on for old log entries.
-
Something may have changed the ruleset numbers between the time the logs were generated and the time you checked. The rule numbers are logged as they happen, and if something changes there, they'll fail to line up from that point on for old log entries.
That makes sense and probably what's going on. However there is one log entry from this morning that has the wrong 'Act', but there has been no config changes made since last night.
Maybe the rule info should/could be included in the firewall log. I know more data to store. :-\
-
Oh, hey, what about a scheduled rule enable/disable. That wouldn't change the rule set numbers would it?
-
I think that can cause such a change. would be easy to check, run "pfctl -sr" when you're in-schedule and again when you're out of the schedule.
-
I think that can cause such a change. would be easy to check, run "pfctl -sr" when you're in-schedule and again when you're out of the schedule.
Yup. It does.
When in schedule the rule is added to the list, shifting down subseqent rules. Causing the firewall log 'Act' to point to the wrong firewall rule. Then removed again when out of schedule, and firewall log 'Act' to again point to the correct firewall rule.
-
I'm going to nitpick you use of "correct" and "incorrect" – all of the log messages are correct at the time they're logged. Whether they line up is a matter of perception at the time the log is viewed :-)
There wouldn't be a good way to log that data "together" without consuming far too many resources to make it worth it. Not that I'm aware of those.
-
Thought that was clear but maybe not.
But anyway. One solution may be to assign a unique ID to each rule. A creation time stamp perhaps, and the firewall log 'Act' could use that to reference the correct associated rule. That way it wouldn't matter if new rules where created / deleted, schedule activated / deactivated, etc. The firewall log would always have a reference to the rule that caused the log entry. Until of course the rule was deleted.
-
It is trickier than it seems. /var/log/filter.log has entries that have rule numbers:
clog /var/log/filter.log | grep "rule 84" Oct 4 08:37:21 pfsense pf: 00:00:00.000000 rule 84/0(match): block in on vr0: (tos 0x0, ttl 128, id 3507, offset 0, flags [DF], proto TCP (6), length 56) Oct 4 08:37:21 pfsense pf: 00:00:00.250417 rule 84/0(match): block in on vr0: (tos 0x0, ttl 128, id 3508, offset 0, flags [DF], proto TCP (6), length 56)then the running pf has its own index of rules, here is a test rule I put in:
pfctl -vvsr | grep reject @84 block return in log quick on vr0 inet from any to 1.2.3.0/24 label "USER_RULE: Test reject 1234"If the "label" value had an index back into the config.xml filter rules array, then anything about the rule in the pfSense config could be looked up. e.g. make "label" say "USER_RULE: 999 Test Reject 1234" - where "999" is a unique ruleid stored in the filter array in config.xml
The tricky bit is that filter.log does not have this "label" text. It contains a rule index into the pf rules of the running pf at the time the entry was logged. If the pf rules are reloaded, then the rule indexes in old filter.log entries are now (potentially) invalid. The original index information from the time of the filter.log entry is gone.
To fix that problem, every time pf rules are reloaded the list of pf rule indexes and rule data (pfctl -vvsr) would have to be saved, along with a timestamp for the ruleset change. Then when filter.log is parsed, the ruleset in use at the time of the filter log entry could be used to find the correct details of the rule index number.
Almost anything is possible, but it sounds like a fair bit of effort!
