Bug #12673


Firewall Logs Widget fails to update at intervals below 5 seconds.

Added by Steve Wheeler about 1 year ago. Updated 4 months ago.

Target version:
Start date:
Due date:
% Done:


Estimated time:
Plus Target Version:
Release Notes:
Affected Version:
Affected Architecture:


As stated the firewall logs dashboard widget fails to update at all if you set an update interval below 5 seconds.

The widget default setting is 60s but allows setting intervals down to 1s. The minimum value should 5 if that's the expected behaviour.

Files (106 KB) Louis B, 11/20/2022 01:24 PM
20221122 (123 KB) 20221122 Improved version, and some related NetGate code (for reference) Louis B, 11/22/2022 07:11 AM
Actions #1

Updated by Steve Wheeler about 1 year ago


2.6.0-BETA (amd64)
built on Sun Jan 09 06:19:32 UTC 2022

Actions #2

Updated by JohnPoz _ about 1 year ago

This is being discussed here

From a quick test, seems to work with 5 seconds, but set to 3 seconds and yeah seems to stall.

Actions #3

Updated by Viktor Gurov about 1 year ago

  • Assignee set to Viktor Gurov
  • Target version changed from CE-Next to 2.7.0
  • Affected Version set to 2.5.2
Actions #4

Updated by Jim Pingle about 1 year ago

  • Status changed from New to Pull Request Review
Actions #5

Updated by Jim Pingle 10 months ago

  • Plus Target Version changed from 22.05 to 22.09
Actions #6

Updated by Jim Pingle 9 months ago

  • Plus Target Version changed from 22.09 to 22.11
Actions #7

Updated by Jim Pingle 6 months ago

  • Plus Target Version changed from 22.11 to 23.01
Actions #8

Updated by Jim Pingle 4 months ago

  • Assignee deleted (Viktor Gurov)
Actions #9

Updated by Jim Pingle 4 months ago

  • Status changed from Pull Request Review to New
  • Plus Target Version changed from 23.01 to 23.05

Needs re-checked to see if it's still a problem and it needs to account for the items I mentioned in the MR. The value there isn't seconds so the proposed change isn't right and if it does work it's only by coincidence.

Actions #10

Updated by Louis B 4 months ago

The problem is clear to me. If the widget processing time > than the refresh time the widget will be re triggered before the screen could be updated. The widget is extremely slow due to design errors.

An obvious one is the fact that it is reading and probably has to read the whole error log due to the possible selection criteria lets take two scenarios:
1) the positive one: The selection is ALL in combination with blocked. Lets assume that the probability of a block in an given firewallog is 1:5 and the requested number of messages is 20. In that case processing of 150 log entry's is almost certain enough
2) the bad one: I select one out of 15 interfaces and I select an interface with hardly any or no traffic ...... you have to read the multi thousand line firewallog and will perhaps even then not 20 lines matching the scenario

Apart from this principle issue, my feeling is that some code speedup is also possible

Actions #11

Updated by Louis B 4 months ago

I did add debug time traces in the widget and it turned out that the html part of the code is causing the terrible delays. Below my time trace.

Further note that:
- someone all-ready limited the number of log lines analyzed by conv_log_filter to 50, which is IMHO low, where I surely agree that there must be an not too high limit
- during processing of the widget the processor load on my relatively powerful FW is raising from 1 to 25%
- the widget refresh time was set on 15 seconds, the time trace shows that the reality is often significant 'lower' (20 seconds is no exception)

However despite some mixed feeling about the php logline selection criteria, it is clear that that is not the bottleneck see the time trace below. Given the fact that the html code directly related to this widget is simple, my feeling is that the real problem is higher up in the dashboard / widget control code.

20221120_16:29:14_After request widgetkey
20221120_16:29:14_After nentries
20221120_16:29:14_After fetch iface_descr_arr
20221120_16:29:14_After filter array definition
20221120_16:29:14_After filling_filter array
20221120_16:29:14_After entries_interval
20221120_16:29:15_After conv_log_filter
20221120_16:29:15_After widgetkey_nodash
20221120_16:29:15_Before foreeach
20221120_16:29:15_Before HTML
20221120_16:29:16_Before HTML
20221120_16:29:17_Before HTML
20221120_16:29:18_Before HTML
20221120_16:29:18_Before HTML
20221120_16:29:19_Before HTML
20221120_16:29:20_Before HTML
20221120_16:29:21_Before HTML
20221120_16:29:21_Before HTML
20221120_16:29:22_Before HTML
20221120_16:29:23_Before HTML
20221120_16:29:24_Before HTML
20221120_16:29:25_Before HTML
20221120_16:29:25_Before HTML
20221120_16:29:26_Before HTML
20221120_16:29:27_Before HTML
20221120_16:29:28_Before HTML
20221120_16:29:28_Before HTML
20221120_16:29:29_Before HTML
20221120_16:29:30_Before HTML
20221120_16:29:30_After foreeach

Actions #12

Updated by Louis B 4 months ago

I did some further analyses, and my previous conclusion was not correct. After making further changes and debugging the conclusion is that the line "$rule = find_rule_by_number($filterent['rulenum'], $filterent['tracker'], $filterent['act']); is causing the problem.

The good news is that with the actual functionality, that line is .... not necessary. The Bad new is that I would love to add the rule description in each second line.

What ever for now I fixed it by simply adding "//" in front of the rule line.

Below the time trace with the rule line active

Analysing firewalllog widget
20221120_19:55:38_After request widgetkey
20221120_19:55:38_After nentries
20221120_19:55:38_After fetch iface_descr_arr
20221120_19:55:38_After filter array definition
20221120_19:55:38_After filling_filter array
20221120_19:55:38_After entries_interval
20221120_19:55:38_After conv_log_filter
20221120_19:55:38_After widgetkey_nodash
20221120_19:55:38_Before foreeach
20221120_19:55:38_Rule lookup did take: 0.778216
20221120_19:55:39_Rule lookup did take: 0.770049
20221120_19:55:40_Rule lookup did take: 0.769228
20221120_19:55:41_Rule lookup did take: 0.769178
20221120_19:55:41_Rule lookup did take: 0.767633
20221120_19:55:42_Rule lookup did take: 0.771554
20221120_19:55:43_Rule lookup did take: 0.767103
20221120_19:55:44_Rule lookup did take: 0.769489
20221120_19:55:45_Rule lookup did take: 0.769441
20221120_19:55:45_Rule lookup did take: 0.769457
20221120_19:55:46_Rule lookup did take: 0.770208
20221120_19:55:47_Rule lookup did take: 0.770610
20221120_19:55:48_Rule lookup did take: 0.769436
20221120_19:55:48_Rule lookup did take: 0.770733
20221120_19:55:49_Rule lookup did take: 0.771599
20221120_19:55:50_Rule lookup did take: 0.770606
20221120_19:55:51_Rule lookup did take: 0.769298
20221120_19:55:52_Rule lookup did take: 0.766164
20221120_19:55:52_Rule lookup did take: 0.768438
20221120_19:55:53_Rule lookup did take: 0.770516
20221120_19:55:53_Before HTML
20221120_19:55:53_After HTML foreeach

Actions #13

Updated by Louis B 4 months ago

Here my code, watch out debug still partly active (to show the speed :)) . The code is more than 150 times faster on my system

Actions #14

Updated by Louis B 4 months ago

The rule lookup function I disable to speedup the widget, was in opposite to my expectation in use to show the rule in case you hoover above the Act-field. That is surely useful functionality, however only possible in case of a very significant(!) performance increase of the find_rule_by_number function!

Note that at this moment the Act-field is based on the rule-lookup but that is not necessary. The act-field is also known without that lookup.

I will have a look at the find_rule_by_number, but fixing that one, is probably more something for NetGate

Actions #15

Updated by Louis B 4 months ago

I think I have solved all issues. The functionality is the same as the original NetGate version. However with a 20 times better performance (in my system, in my setup).

Next to that it processes a maximum of 250 lines from the firewall log in opposite to only 50 in the original version (which is relevant if you e.g. would like to select alarms from one specific interface). I also shorted the timestamps printout, since I did not like it and assume nearly any one is interested to see the micro seconds.

Attached the code


Also available in: Atom PDF