System logs don't show all local log entries?

[Lasse]

Hi all,

First post, so mini-introduction: we switched our <100 employee network from Checkpoint to PfSense and love the latter so much more that we bought an SG-4860 after running pfSense on an old, total overkill server for about a year. Thanks for the great work!

While troubleshooting traffic problems between servers in our subnets (with PfSense 2.3.1 p5 on our new SG-4860) I noticed that the filtered system logs shown in the web GUI don't include all log lines included in the log files. Only the most recent lines appear to be shown in the GUI which is quite annoying and rather odd imho. Is this caused by some setting that I've missed or could this be a bug in the new GUI?

The situation in a little more detail:
There's traffic from server A to server B which is blocked by a rule in PfSense with activated logging (all working nicely).
When filtering the GUI system logs to see all entries of this event with A as the source, all entries are shown for the last 3 hours (in this case 10 entries).
When filtering the system logs with clog /var/log/filter.log | grep A through ssh, all entries are shown for the last 4.5 hours (in this case 16 entries). All entries show A as the source (not the destination).

Checking other entries shows the same result and it doesn't appear to be caused by the max. amount of entries shown in the GUI which in this case cuts off at another point in time. Probably unrelated but just in case: we also use a syslog-server for long-term logs and this also works fine (showing the much longer term history than the local logs).

Thanks in advance for any ideas!
Lasse

[cmb]

It shows however many lines you have it configured to display, 50 by default.

[Lasse]

I set the amount of entries to be shown at 1000 (which it does without filter), so that shouldn't be the cause of it showing only 10 of 16 filtered log entries.

Attached screenshots show GUI logfilter selection (red=ipA, green=ipB; now only showing 9 of the 16 entries) and settings.

clog filter.log | grep ipA

Jul 26 13:27:13 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4825,0,none,17,udp,67,ipA,ipB,21362,53,47
Jul 26 13:28:36 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4826,0,none,17,udp,67,ipA,ipB,12143,53,47
Jul 26 13:47:22 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4827,0,none,17,udp,67,ipA,ipB,47163,53,47
Jul 26 13:48:45 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4828,0,none,17,udp,67,ipA,ipB,42579,53,47
Jul 26 13:55:28 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4530,0,none,17,udp,66,ipA,ipB,13852,53,46
Jul 26 13:55:31 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4809,0,none,17,udp,66,ipA,ipB,18980,53,46
Jul 26 14:07:31 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4829,0,none,17,udp,67,ipA,ipB,28907,53,47
Jul 26 14:08:54 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4830,0,none,17,udp,67,ipA,ipB,29212,53,47
Jul 26 14:27:40 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4831,0,none,17,udp,67,ipA,ipB,12934,53,47
Jul 26 14:29:04 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4832,0,none,17,udp,67,ipA,ipB,54901,53,47
Jul 26 14:47:50 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4833,0,none,17,udp,67,ipA,ipB,22571,53,47
Jul 26 14:49:13 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4834,0,none,17,udp,67,ipA,ipB,25051,53,47
Jul 26 15:07:58 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4835,0,none,17,udp,67,ipA,ipB,45112,53,47
Jul 26 15:09:23 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4836,0,none,17,udp,67,ipA,ipB,34552,53,47
Jul 26 15:28:08 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4837,0,none,17,udp,67,ipA,ipB,10890,53,47
Jul 26 15:29:31 pfSense filterlog: 154,16777216,,1448275809,igb0_vlan10,match,block,in,4,0x0,,255,4838,0,none,17,udp,67,ipA,ipB,56955,53,47


[NOYB]

What happens if the log is shown in forward order?
What happens if the quantity is set real high.  Like the number of log entries?

Don't quote me on this, it's been a long time since I worked on the filtering, but it seems perhaps I recall that reverser order only include the specified quantity plus some overflow in the filtering.  So if some of the entries are from before or after that they could be missed.

Update:
Don't know your technical level, but if you think you are up to it you might edit /etc/inc/filter_log.inc and near line 70 where the following is found.  Up 5000 to say maybe 10000 or so, to see if that captures all of the expected entries.

	if ($filtertext) {
		$tail = 5000;
	}

Update 2:
On second thought, that code snip may only be relevant to "raw" display mode.

[Lasse]

Thanks for the suggestions, NOYB. Unfortunately disactivating reverse order and/or setting the quantity real high (also 1000) yield the same result.

[NOYB]

@Lasse:

Thanks for the suggestions, NOYB. Unfortunately disactivating reverse order and/or setting the quantity real high (also 1000) yield the same result.

Thought you already had it set at 1000.  Try 10000 (ten thousand).

[Lasse]

Yes, in the general log settings it was already set at 1000 but not in the filter specific rules. 10000 and 100000 in the filter rule yield the same result.

[NOYB]

@Lasse:

Yes, in the general log settings it was already set at 1000 but not in the filter specific rules. 10000 and 100000 in the filter rule yield the same result.

Okay thanks for the clarification/verification.

Could you post the string being used in the filter.  Replacing only each digit with an 'x'?  This really isn't a string but a regex pattern.  So I'd like to see the pattern.  I'm guess you it's just a ordinary IPv4 address in the form of d.d.d.d.  You might try this, but it is a long shot. ```
d.d.d.d

[Lasse]

Yes, it's a normal IPv4 address: xx.xxx.x.xx .
xx.xxx.x.xx yields the same result as well, but thanks for trying anyway :)

Could anyone please check whether or not their system shows the same behavior to be sure that this is not specific to our setup?

[NOYB]

How many log entries are there after the Jul 26 13:27:13 entry?  (total, not filtered in any way)

[Derelict]

Does what I tell it to do here.

Are you sure the log entries not being displayed haven't "scrolled off" between the time you looked at the clog output and the time you ran the filtered system log output?

clog /var/log/filter.log | grep 192.168.223.5 | wc -l
    988


[NOYB]

Works here for me too.  Clog | grep and GUI Filter both give the same quantity.

With a 20,000,000 log file size there could be a lot of entries.  Like about 40 times more than the default.  I'm thinking some limit with the filtering is being bumped into.

[Lasse]

Thanks for checking! I'll try to reduce the log file size but will have to turn off some logging in order to be able to see enough (a couple of days) history then.

NOYB, clog shows 12153 entries and Jul 26 13:27:13 is at line 533, so 11620 entries after that first entry.

Derelict, rechecked and still the same difference (currently 45 vs 38). Looks like your GUI shows 10 more entries than the clog count? (988 vs 998; due to time difference?)

[NOYB]

@Lasse:

Thanks for checking! I'll try to reduce the log file size but will have to turn off some logging in order to be able to see enough (a couple of days) history then.

NOYB, clog shows 12153 entries and Jul 26 13:27:13 is at line 533, so 11620 entries after that first entry.

Derelict, rechecked and still the same difference (currently 45 vs 38). Looks like your GUI shows 10 more entries than the clog count? (988 vs 998; due to time difference?)

The part that I think is potentially causing the issue would be the quantity of entries after the first entry of interest.  The code does a reverse tail to grab the end of the log file.  Just a guess but I think the size of the tail comes from the filter quantity.  But even if it does, with that amount of entries, there could be some other limit being bumped into.  Maybe the display quantity plays a roll too but I don't think so.  Does a reverse tail maybe have some limit?

~line 145 /etc/inc/filter_log.inc

	exec("/usr/local/sbin/clog " . escapeshellarg($logfile) . " | /usr/bin/grep -v \"CLOG\" | /usr/bin/grep -v \"\033\" | /usr/bin/grep -E $pattern | /usr/bin/tail -r -n {$tail}", $logarr);

[Lasse]

Looks like the reverse tail works fine (verified resulting tail output as well):
clog /var/log/filter.log | tail -r -n 11500 | wc -l
  11500

Also, the following works fine and shows all entries:
clog /var/log/filter.log | grep ipA | tail -r -n 1000

[NOYB]

Earlier I mentioned this code snip and possibly bumping up that tail quantity.  I think the intention was for it to only apply to raw mode.  But it may be getting applied to formatted mode too.  Or maybe it is supposed to be applied to both modes.  But either way I think there is a high probability this is the cause of the limitation.

In formatted mode $filtertext I think contains an array, which maybe is evaluating to true.  (comes from /usr/local/www/status_logs_common.inc)

~ line 70 /etc/inc/filter_log.inc

	if ($filtertext) {
		$tail = 5000;
	}

[Lasse]

Missed your updates of that post, sorry. The raw filter log does show all entries when filtering by ipA by the way.
Altered $tail from 5000 to 15000 in /etc/inc/filter_log.inc and this fixed the issue for the formatted log filtering. Thanks a lot! :)

I assume $tail was hardcoded at 5000 for performance reasons on slow machines? Maybe this should be a little higher by default? I might increase my log size again and up $tail some more (unless someone points out downsides to this strategy?).

update:
The following command leads to the same result as the default GUI filter log, hence the difference and possible incompleteness:
clog /var/log/filter.log | tail -r -n 5000 | grep ipA
Which obviously can show less than
clog /var/log/filter.log | grep ipA | tail -r -n 5000

[NOYB]

@Lasse:

Missed your updates of that post, sorry. The raw filter log does show all entries when filtering by ipA by the way.
Altered $tail from 5000 to 15000 in /etc/inc/filter_log.inc and this fixed the issue for the formatted log filtering. Thanks a lot! :)

I assume $tail was hardcoded at 5000 for performance reasons on slow machines? Maybe this should be a little higher by default? I might increase my log size again and up $tail some more (unless someone points out downsides to this strategy?).

Awesome.  Great.  Now it just needs to be determined if that is supposed to be applied to both formatted and raw modes or just raw.  And what the value should be.

Yeah most likely performance was the reason for that.  But I don't actually know that for a fact.  You are in uncharted waters now.  No guarantees.

[NOYB]

After pondering it a few moments I think it is intended for both modes.

I think the purpose was to ensure a large enough quantity of log entries would be grabbed for the filter (either formatted - $filterfieldsarray, or raw mode - $filtertext).  Otherwise use $nentries that was passed.

If this is correct then the value probably should be bumped up or set in some relation to the log size.  $nentries, which comes from the filter quantity still gets used for the quantity to display though, and I think overrides the general display quantity setting.

There's a lot packed in there.  May take a few read throughs to get it all.

[Lasse]

Wouldn't replacing $tail with +1 for the tail command read the entire log file, regardless of size, and solve the issue? If too slow, users would then have to reduce log size. Simply replacing {$tail} with +1 in the next line doesn't work though.

exec("/usr/local/sbin/clog " . escapeshellarg($logfile) . " | /usr/bin/grep -v \"CLOG\" | /usr/bin/grep -v \"\033\" | /usr/bin/grep -E $pattern | /usr/bin/tail -r -n {$tail}", $logarr);

Edit: looks like it works fine without the -n argument as -r by default will read all lines:

exec("/usr/local/sbin/clog " . escapeshellarg($logfile) . " | /usr/bin/grep -v \"CLOG\" | /usr/bin/grep -v \"\033\" | /usr/bin/grep -E $pattern | /usr/bin/tail -r", $logarr);

Shall I request this to be added through github?