System logs don't show all local log entries?



  • 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



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



  • 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
    

    ![Screenshot from 2016-07-27 09:10:39.png](/public/imported_attachments/1/Screenshot from 2016-07-27 09:10:39.png)
    ![Screenshot from 2016-07-27 09:10:39.png_thumb](/public/imported_attachments/1/Screenshot from 2016-07-27 09:10:39.png_thumb)
    ![Screenshot from 2016-07-27 09:08:56.png](/public/imported_attachments/1/Screenshot from 2016-07-27 09:08:56.png)
    ![Screenshot from 2016-07-27 09:08:56.png_thumb](/public/imported_attachments/1/Screenshot from 2016-07-27 09:08:56.png_thumb)



  • 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.



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



  • @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).



  • 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.



  • @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



  • 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?



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


  • LAYER 8 Netgate

    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

    ![Screen Shot 2016-07-27 at 1.38.30 AM.png](/public/imported_attachments/1/Screen Shot 2016-07-27 at 1.38.30 AM.png)
    ![Screen Shot 2016-07-27 at 1.38.30 AM.png_thumb](/public/imported_attachments/1/Screen Shot 2016-07-27 at 1.38.30 AM.png_thumb)



  • 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.



  • 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?)



  • @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);
    
    


  • 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



  • 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;
    	}
    
    


  • 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



  • @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.



  • 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.



  • 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?



  • Or better, as this does not slow down showing the logs when if($filtertext) returns false:

            if ($filtertext) {
                    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);
            } else {
                    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);
            }
    


  • My concern with not having some sort of fail-safe limit would be that someone with a large log and little memory etc. does a filter and crashes the system.

    Would be nice if need of the intermediate save to variable for processing could be eliminated from the filtering.



  • The 5000 number may have its roots in being more than any of the logs could contain with the default size.

    If that is the case then an equivalent for your 20 meg log files would be about 200,000 (40x).



  • Been mulling this over today and think that it should be fairly safe to open it up to include entire log when $filtertext parameter is passed.  The reasoning for this is that the largest the storage variable should become is the size of the log file.  In your case about 20 meg.  Hopefully those with lesser capable systems would not bump up the log file size so dramatically as to become a problem.
    Also from a cursory web search it sounds like php should just stop and throw an error.

    But I'll leave this decision to someone at a higher pay grade than I, since how PHP/pfSense/FreeBSD/etc. will actually respond is beyond my knowledge.

    If the direction is to open it up to ensure inclusion of the entire log when $filtertext parameter is passed, I'd prefer it be done something like this.  The tail '-r' option automatically grabs all lines.  So '-n' option can be omitted.

    When $filtertext parameter is not passed then use the use the tail -n option value as-is since all that is needed is that number of entries.

    ~ line 69 - /etc/inc/filter.inc

    
    	if ($filtertext) {
    		$log_tail_opts = '-r';
    	} else {
    		$log_tail_opts = '-r -n ' . $tail;
    	}
    
    

    ~ line 146 - /etc/inc/filter.inc

    
    	# Get a bunch of log entries.
    	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 {$log_tail_opts}", $logarr);
    
    



  • Rebel Alliance Developer Netgate

    The original 5000 was set back when the log itself was only likely to contain ~2500 entries. It was a sanity check.

    The intermediate save can't be avoided because of the way the firewall log filtering code has been changed. It can't filter on only specific fields without that step.

    Now that the log sizes are adjustable, we could probably increase that limit, but I'd be afraid at some point it would run PHP out of memory. 10k seems like it might be OK.

    At some point you are trying to push the logging limits of the firewall too far, however. If you really need to search that far back in your history, you should probably be exporting the logs to a proper syslog server with long-term searchable storage.



  • Yup we are on the same page.

    Too bad clog doesn't have reverse and line by line capability (similar to fgets line by line).  Then the intermediate storage variable could be eliminated I think.  Just need a way to read the log file backwards and line by line and I think the intermediate step could be eliminated.


Log in to reply