Bug #12673
closed
Firewall Logs Dashboard Widget is slow and may fail to update
Added by Steve Wheeler almost 3 years ago. Updated 7 months ago.
100%
Description
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
| widget.zip (106 KB) widget.zip | Louis B, 11/20/2022 01:24 PM | ||
| 20221122 FW-log-widget.zip (123 KB) 20221122 FW-log-widget.zip | Improved version, and some related NetGate code (for reference) | Louis B, 11/22/2022 07:11 AM | |
| 20240228 fwlog.inc.zip (737 Bytes) 20240228 fwlog.inc.zip | Louis B, 02/28/2024 01:39 PM | ||
| 20240228 fwlog.widget.zip (6.38 KB) 20240228 fwlog.widget.zip | Louis B, 02/28/2024 01:43 PM |
Related issues
Updated by Steve Wheeler almost 3 years ago
Tested:
2.6.0-BETA (amd64) built on Sun Jan 09 06:19:32 UTC 2022 FreeBSD 12.3-STABLE
Updated by JohnPoz _ almost 3 years ago
This is being discussed here
https://forum.netgate.com/topic/168895/please-help-firewall-logs-dashboard-widget-not-updating
From a quick test, seems to work with 5 seconds, but set to 3 seconds and yeah seems to stall.
Updated by Viktor Gurov almost 3 years ago
- Assignee set to Viktor Gurov
- Target version changed from CE-Next to 2.7.0
- Affected Version set to 2.5.2
Updated by Jim Pingle almost 3 years ago
- Status changed from New to Pull Request Review
Updated by Jim Pingle over 2 years ago
- Plus Target Version changed from 22.05 to 22.09
Updated by Jim Pingle over 2 years ago
- Plus Target Version changed from 22.09 to 22.11
Updated by Jim Pingle about 2 years ago
- Plus Target Version changed from 22.11 to 23.01
Updated by Jim Pingle about 2 years 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.
Updated by Louis B about 2 years 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
Updated by Louis B about 2 years 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_^START^
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
Updated by Louis B about 2 years 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_^START^
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
Updated by Louis B about 2 years ago
- File widget.zip widget.zip added
Here my code, watch out debug still partly active (to show the speed :)) . The code is more than 150 times faster on my system
Updated by Louis B about 2 years 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
Updated by Louis B about 2 years 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
Updated by Jim Pingle over 1 year ago
- Plus Target Version changed from 23.05 to 23.09
Can you submit the proposed changes as a pull request on Github?
https://docs.netgate.com/pfsense/en/latest/development/pull-request.html
Updated by Jim Pingle over 1 year ago
- Target version changed from 2.7.0 to CE-Next
Updated by Jim Pingle over 1 year ago
- Plus Target Version changed from 23.09 to 24.01
Updated by Jim Pingle about 1 year ago
- Plus Target Version changed from 24.01 to 24.03
Updated by Louis B 9 months ago
My version of the log-widget is way faster (20 times!) than the actual version. With the same GUI and the same functionallity. I really hope that netgate will integrate it in pfSense. I attached the code long ago (see above).
Jim's replay above indicates that it I need to create a GIT-project for that etc for that.
Really!! I am not a GIT-expert. So that would be significant work for me.
I did pull the netgate log-widget code and did make the modifications to make it (a lot) faster. So in my opinion it can't be hard for NetGate to create a project branch using my code and to compare that with the actual log-widget branche. That whould save me a lot of time!
Updated by Steve Wheeler 9 months ago
Doing so it pretty trivial. It requires almost no skill. (ask me how I know!).
Create github account.
Fork pfsense/pfsense
Edit the code in your fork.
When you push the changes select make a pull request. Reference this bug report.
Which of the files in the zip above are actually changed? Does it still apply against 24.03?
Updated by Louis B 9 months ago
- File 20240228 fwlog.inc.zip 20240228 fwlog.inc.zip added
- File 20240228 fwlog.widget.zip 20240228 fwlog.widget.zip added
Please update firewall log widget, with attached code
Steve,
- It is probably not complex, but never the less, Why?
- I do have a Github account since long, but I rarely use it
- Tried to integrate php and Github in visual studio, not a success (yet), so I used an editor
I did write the new firewall log widget code two years ago and used it since then (now running 23.09.1-RELEASE (amd64))
Last week I did download the actual netgate version from github and did some small modifications, mainly related to the changed used html special characters
And did test the result by uploading the "fwlog.inc" and "fwlog.widget.php" to my firewall
Of course I could have replaced the netgate files as well, by replacing "log.inc" and "log.widget.php"
The main difference between my version and the netgate version is that the netgate version processes ^log entry" by "log entry" where my version fetches "a set of log entry's" and process them in one go. The processing speed for all logs to be processed, is hardly more that that of one single entry leading to a 20 fold speed improvement.
The attached code does include a lot of debug lines mostly preceded by comment signs. I left them in so that the debugging I did can simply be reproduced.
Needed actions:
- upload widget to /usr/local/www/widgets/widgets
- upload inc file to /usr/local/www/widgets/include
- perhaps make a small change to the widget menu
- compare with actual branch for info, note that there is significant code added
around the original code, leaving the original code unchanged as far as possible
- some testing and if wanted debugging mainly to see the speed improvement
Attached the actual files
Perhaps I will try to send the files via github, to learn, but IMHO it does not have added value
Updated by Louis B 9 months ago
I just created a pull request Updated much faster log.widget Bug #12673 #4672
I left debug statements in the code so that it is easy to trace what is exactly happening. I also used the added debug lines (partly starting with comment sign //) to trace which statement / calls where causing all the delays. Debug can of course be removed (if you prefer)
Updated by Steve Wheeler 9 months ago
- Status changed from New to In Progress
Yes it's here: https://github.com/pfsense/pfsense/pull/4672
Updated by Steve Wheeler 9 months ago
- Target version changed from CE-Next to 2.8.0
Seems to apply and work as expected against a 2.8 snapshot.
Updated by Jim Pingle 9 months ago
- Status changed from In Progress to Feedback
- Assignee set to Jim Pingle
- % Done changed from 0 to 100
The PR was creating a new file instead of updating the existing one and had some whitespace/formatting issues but I cleaned it up and committed it manually. See 1586f580e6ce8f39cb235b0bdc14d470501f7714 which should show up shortly.
Thanks!
Updated by Steve Wheeler 8 months ago
- Related to Regression #15339: Firewall logs widget cannot have multiple instances added
Updated by Jim Pingle 8 months ago
- Subject changed from Firewall Logs Widget fails to update at intervals below 5 seconds. to Firewall Logs Dashboard Widget is slow and may fail to update
Somewhere along the way this changed from the initial issue (updates fail if < 5 seconds) and became about the speed of the widget.
The widget works and is faster now, but the original problem is still there: It won't update if you enter an interval < 5 seconds.
I set the lower boundary on the widget to be 5 seconds now to at least stop that case, though I suspect there may be other problems looking at the code involved. I'll split that off into a new issue for a later release.
Updated by Jim Pingle 8 months ago
- Related to Bug #15373: Firewall Logs Dashboard widget update interval does not behave as expected added