Bug #12747
closedRestarting the logging daemon during rotation also restarts ``sshguard``, leading to frequent log messages
100%
Description
sshguard has to restart when he logs are rotated in 2.6 in order to monitor the current file. When it does so it logs the service restart.
In an even moderately busy firewall this can produce a lot of log entries to the point it starts to hide other more important logs.
It appears to restart whenever any log is rotated, is that actually required?
For example on a test system where an IPSec tunnel is configured but never connects the ipsec log rotates frequently resulting in a system log:
Jan 31 00:25:00 sshguard 29496 Exiting on signal. Jan 31 00:25:00 sshguard 9940 Now monitoring attacks. Jan 31 03:17:00 sshguard 9940 Exiting on signal. Jan 31 03:17:00 sshguard 60321 Now monitoring attacks. Jan 31 06:09:00 sshguard 60321 Exiting on signal. Jan 31 06:09:00 sshguard 83661 Now monitoring attacks. Jan 31 09:01:00 sshguard 83661 Exiting on signal. Jan 31 09:01:00 sshguard 93166 Now monitoring attacks. Jan 31 11:53:00 sshguard 93166 Exiting on signal. Jan 31 11:53:00 sshguard 94019 Now monitoring attacks.
It's possible to mitigate this to some extent by increasing the log file size reducing the rotation frequency.
Files
Updated by Todd Marimon almost 3 years ago
I am seeing this as well. In my case it seems to be every 2 minutes-- quite a lot of log noise! On pfSense 2.6.0.
Feb 24 00:13:00 sshguard 62471 Now monitoring attacks. Feb 24 00:13:00 sshguard 28882 Exiting on signal. Feb 24 00:11:00 sshguard 28882 Now monitoring attacks. Feb 24 00:11:00 sshguard 90479 Exiting on signal. Feb 24 00:09:00 sshguard 90479 Now monitoring attacks. Feb 24 00:09:00 sshguard 60259 Exiting on signal. Feb 24 00:07:00 sshguard 60259 Now monitoring attacks. Feb 24 00:07:00 sshguard 98243 Exiting on signal. Feb 24 00:05:00 sshguard 98243 Now monitoring attacks. Feb 24 00:05:00 sshguard 994 Exiting on signal.
Updated by Michael TRVL ALBT over 2 years ago
Having the same issue since 2.6.0 too.
Updated by Marle Cua-chin over 2 years ago
I'm also experiencing the same issue on 2.6.0
Updated by Antonio Pesce over 2 years ago
I'm having the same issue on 2.6.0 on 6 pfSense instance.
Updated by Franck Ck over 2 years ago
same here on 22.05
Updated by Geovane Gonçalves over 2 years ago
I'm having the same issue on 2.6.0 at every 1 minute:
Jul 5 09:33:00 sshguard 77002 Exiting on signal.
Jul 5 09:33:00 sshguard 19637 Now monitoring attacks.
Jul 5 09:34:00 sshguard 19637 Exiting on signal.
Jul 5 09:34:00 sshguard 40779 Now monitoring attacks.
Jul 5 09:35:00 sshguard 40779 Exiting on signal.
Jul 5 09:35:00 sshguard 64718 Now monitoring attacks.
Jul 5 09:36:00 sshguard 64718 Exiting on signal.
Jul 5 09:36:00 sshguard 6061 Now monitoring attacks.
Jul 5 09:37:00 sshguard 6061 Exiting on signal.
Jul 5 09:37:00 sshguard 46190 Now monitoring attacks.
As a workaround I disabled the log packets matched from the default block rules in the ruleset to reduce the amount of system logs, but that didn't happen before the upgrade. The frequency has dropped and now I'm watching.
After a period of calm, he logged back in every minute. Maybe on restart of syslogd. I changed the file size from 500K to 1024 and I'm tracking again.
Doubling the size of the logs from 512K to 1024K didn't work either. After about a day the logs became polluted again. No solution.
Updated by van trung tran almost 2 years ago
I am having the same issue in 22.05. Netgate XG1541
Updated by Michael Kellogg almost 2 years ago
I am Still seeing this on 2.7 built on Fri Jan 20 03:01:02 UTC 2023
seems like every 5-10 minutes not a pattern i can figure out
Updated by Mitch Claborn over 1 year ago
Still an issue in 23.01. Suggestions:
1. Stop logging the stop and start. I can't see how this is useful.
2. Make sshguard smart enough to recognize a new log file without restarting. (e.g. send it a HUP to look for new log files)
3. Allow filtering on the log display to hide entries that we don't want to look at.
Updated by Jim Pingle over 1 year ago
Unfortunately a lot of this is out of our control as we are at the mercy of what sshguard supports. Not saying we won't keep looking for a solution, but that our options here are limited.
The way it is currently used, sshguard will restart when syslogd restarts, which will happen any time a log is rotated. If your logs are rotating that fast, you should figure out what is causing such a high volume of logs and take some sort of corrective actions:
- Reduce the logging of whatever is causing the high volume of logs
- Increase the log rotation size of the affected log (or all logs)
- Disable local logging and rely solely on remote logging
That high volume of logging would also be causing a high volume of disk writes on your device, which is likely undesirable as well.
Updated by Jonathan Stafford about 1 year ago
- File clipboard-202309230719-waesz.png clipboard-202309230719-waesz.png added
- File clipboard-202309230720-yhwfb.png clipboard-202309230720-yhwfb.png added
I'm having this problem as well, with 23.05.1-RELEASE. For me, the issue seems to be that the filter logs are rolling every 45 minutes to an hour:
The vast majority of the logs are coming from what I assume are system rules, the 1000000??? entries. These don't match the tracking ids of any rules I have defined.
- 1000000003 - Mostly IPv6 mDNS on the LAN interface, although there is some DHCPv6 and ICMPv6.
- 1000000103 - Most of the logs are IPv4 on the WAN interface addressed to my WAN IP. A few of the logs are on the LAN interface, to an assortment of IPs on 443.
- 1000000004 - DHCPv6 from the WAN and ICMPv6 from the LAN
I do not have IPv6 enabled at System/Advanced/Networking/IPv6 Options->Allow IPv6. Additionally, it's a TP Link SG108E connected to the LAN port, which doesn't support IPv6 anyway ... so not really clear where this is even coming from. I don't know enough about the log format to swear this isn't 6in4. I have my own rules on the WAN and LAN to drop IPv6, but these never show any hits.
I have gotten an IPv6 address from my ISP in the past, but with no ability to use IPv6 on the network I turned that off.
I did just add some rules to drop 6in4 traffic in both directions and those haven't immediately shown any matches.
Looking through the various configuration pages, I don't see any way to enable/disable logging hits on system rules, but certainly could have missed it. Gonçalves, where did you see that? Ah it's at Status/System Logs/Settings/General Logging Options->Log firewall default blocks. At least now I don't know about this weird IPv6 traffic :)
Updated by Geovane Gonçalves about 1 year ago
Jonathan Stafford wrote in #note-14:
I'm having this problem as well, with 23.05.1-RELEASE. For me, the issue seems to be that the filter logs are rolling every 45 minutes to an hour:
The vast majority of the logs are coming from what I assume are system rules, the 1000000??? entries. These don't match the tracking ids of any rules I have defined.
As far as I can tell these rules are matching:
- 1000000003 - Mostly IPv6 mDNS on the LAN interface, although there is some DHCPv6 and ICMPv6.
- 1000000103 - Most of the logs are IPv4 on the WAN interface addressed to my WAN IP. A few of the logs are on the LAN interface, to an assortment of IPs on 443.
- 1000000004 - DHCPv6 from the WAN and ICMPv6 from the LAN
I do not have IPv6 enabled at System/Advanced/Networking/IPv6 Options->Allow IPv6. Additionally, it's a TP Link SG108E connected to the LAN port, which doesn't support IPv6 anyway ... so not really clear where this is even coming from. I don't know enough about the log format to swear this isn't 6in4. I have my own rules on the WAN and LAN to drop IPv6, but these never show any hits.
I have gotten an IPv6 address from my ISP in the past, but with no ability to use IPv6 on the network I turned that off.
I did just add some rules to drop 6in4 traffic in both directions and those haven't immediately shown any matches.
Looking through the various configuration pages, I don't see any way to enable/disable logging hits on system rules, but certainly could have missed it. Gonçalves, where did you see that?Ah it's at Status/System Logs/Settings/General Logging Options->Log firewall default blocks. At least now I don't know about this weird IPv6 traffic :)
Maybe it helps:
I believe that we have reached a suitable configuration for our case.
I'll report the actions in case anyone finds this useful in the future:
PfSense 2.6.0 - FW/GW/Proxy wifi network approx 1300 daily users.
Logs are sent remotely for auditing purposes. Lots of filter logs!
Our final configuration to avoid "sshguard" spam looked like this:
We increased log file size to 100MB;
To avoid excessive disk consumption, retention has been changed to only two files in "log settings";rw------ 1 root wheel 97239550 Jul 14 11:35 filter.logrw------ 1 root wheel 102682474 Jul 13 16:16 filter.log.0rw------ 1 root wheel 102697059 Jul 13 11:31 filter.log.1
To avoid the risk of unnecessary CPU consumption, log compression was disabled (UFS);
We disabled the log packets matched from the default block rules in the ruleset to reduce the amount of system logs;
We reviewed the other firewall rules and kept the logs strictly necessary;
Also to avoid space consumption, squid log retention has been reduced from 30 to 3 files.
Thanks,
Geovane
original post:
https://forum.netgate.com/topic/169923/tons-sshguard-log-entries-and-its-not-enabled/63?lang=pt-BR
Updated by Daryl Morse 9 months ago
The original bug was reported against 2.6.0, but the problem has carried over to 2.7.x.
These messages are only one example of how the logs are being literally polluted by useless garbage messages. This is not cosmetic. Garbage messages cause important messages to be lost. The fix is not to reduce the size of the logs. The fix is to eliminate the garbage either by preventing them from being generated in the first place or if that isn't possible, by filtering them after they are created so there is room in the log for important messages.
Updated by → luckman212 4 months ago
Damn. I got bit by this today when trying to troubleshoot a remote firewall. Filled to the brim with the logspew (pfSense+ 24.03)
Updated by Christopher Cope 4 months ago
Marcos M wrote in #note-18:
Here's a patch for 24.03 for testing: {{collapse
[...]
}}Apply then reboot.
Tested on 24.03 and it seems to be working as intended. Even when syslogd is restarted, sshguard doesn't fill the logs. sshguard logs are also nicely placed into /var/log/sshguard.log. The logs are much more readable.
Updated by Marcos M 3 months ago
- Status changed from Ready To Test to Feedback
- Assignee set to Marcos M
- Target version changed from CE-Next to 2.8.0
- Plus Target Version changed from Plus-Next to 24.08
With f32dca244955da9007e1bc75801d486b5f70352e sshguard now monitors auth.log directly instead of relying on syslogd to send it messages.
Edit: I've pushed an additional change to remove an unnecessary service restart: commit:a82bb079330fb681b9d7c6eb1e52ae2484f84c04
Updated by Danilo Zrenjanin 3 months ago
- Status changed from Feedback to Resolved
I was able to reproduce the issue on 24.03.
After applying the patch, I got the same results.
Aug 22 15:11:00 sshguard 15993 Now monitoring attacks. Aug 22 15:11:00 sshguard 55230 Exiting on signal. Aug 22 15:08:00 sshguard 55230 Now monitoring attacks. Aug 22 15:08:00 sshguard 97999 Exiting on signal. Aug 22 15:05:00 sshguard 97999 Now monitoring attacks. Aug 22 15:05:00 sshguard 33690 Exiting on signal. Aug 22 15:02:00 sshguard 33690 Now monitoring attacks. Aug 22 15:02:00 sshguard 30903 Exiting on signal. Aug 22 14:59:05 php-fpm 536 System Patches: Patch fetched successfully (ID: 66c752367f64b, DESCR: ssh_logs) Aug 22 14:59:05 check_reload_status 589 Syncing firewall Aug 22 14:59:05 php-fpm 536 /system_patches.php: Configuration Change: admin@192.168.33.1 (Local Database): Fetched patch ssh_logs Aug 22 14:59:02 check_reload_status 589 Syncing firewall Aug 22 14:59:02 php-fpm 92470 /system_patches_edit.php: Configuration Change: admin@192.168.33.1 (Local Database): System: Patches: edited a patch. Aug 22 14:58:25 pkg-static 54621 pfSense-pkg-System_Patches-2.2.11_15 installed Aug 22 14:58:25 php 65227 //etc/rc.packages: Successfully installed package: System Patches. Aug 22 14:58:25 php 65227 //etc/rc.packages: Configuration Change: (system): Installed System Patches package. Aug 22 14:58:25 check_reload_status 589 Syncing firewall Aug 22 14:58:25 php 65227 //etc/rc.packages: Configuration Change: (system): System Patches package added an early shellcmd: apply patches Aug 22 14:58:25 check_reload_status 589 Syncing firewall Aug 22 14:58:25 php 65227 //etc/rc.packages: Configuration Change: (system): Intermediate config write during package install for System Patches. Aug 22 14:58:25 php 65227 //etc/rc.packages: Beginning package installation for System Patches . Aug 22 14:58:21 check_reload_status 589 Syncing firewall Aug 22 14:58:21 php-fpm 69927 /pkg_mgr_install.php: Configuration Change: admin@192.168.33.1 (Local Database): Creating restore point before package installation. Aug 22 14:58:00 sshguard 30903 Now monitoring attacks. Aug 22 14:58:00 sshguard 87083 Exiting on signal. Aug 22 14:57:10 php-fpm 69927 /pkg_mgr_installed.php: The command '/usr/local/sbin/pfSense-repo-setup' returned exit code '14', the output was '' Aug 22 14:52:00 sshguard 87083 Now monitoring attacks. Aug 22 14:52:00 sshguard 54118 Exiting on signal. Aug 22 14:46:00 sshguard 54118 Now monitoring attacks. Aug 22 14:46:00 sshguard 32464 Exiting on signal. Aug 22 14:40:00 sshguard 32464 Now monitoring attacks. Aug 22 14:40:00 sshguard 17167 Exiting on signal. Aug 22 14:34:00 sshguard 17167 Now monitoring attacks. Aug 22 14:34:00 sshguard 95472 Exiting on signal. Aug 22 14:28:00 sshguard 95472 Now monitoring attacks. Aug 22 14:28:00 sshguard 62604 Exiting on signal. Aug 22 14:22:00 sshguard 62604 Now monitoring attacks. Aug 22 14:22:00 sshguard 41788 Exiting on signal. Aug 22 14:16:00 sshguard 41788 Now monitoring attacks. Aug 22 14:16:00 sshguard 11625 Exiting on signal. Aug 22 14:10:00 sshguard 11625 Now monitoring attacks. Aug 22 14:10:00 sshguard 83934 Exiting on signal. Aug 22 14:04:00 sshguard 83934 Now monitoring attacks. Aug 22 14:04:00 sshguard 52778 Exiting on signal. Aug 22 13:58:00 sshguard 52778 Now monitoring attacks. Aug 22 13:58:00 sshguard 45828 Exiting on signal. Aug 22 13:52:00 sshguard 45828 Now monitoring attacks. Aug 22 13:52:00 sshguard 9833 Exiting on signal. Aug 22 13:46:00 sshguard 9833 Now monitoring attacks. Aug 22 13:46:00 sshguard 82710 Exiting on signal. Aug 22 13:40:00 sshguard 82710 Now monitoring attacks. Aug 22 13:40:00 sshguard 56637 Exiting on signal. Aug 22 13:34:00 sshguard 56637 Now monitoring attacks. Aug 22 13:34:00 sshguard 29766 Exiting on signal. Aug 22 13:28:00 sshguard 29766 Now monitoring attacks. Aug 22 13:28:00 sshguard 96576 Exiting on signal. Aug 22 13:22:00 sshguard 96576 Now monitoring attacks. Aug 22 13:22:00 sshguard 72471 Exiting on signal. Aug 22 13:16:00 sshguard 72471 Now monitoring attacks. Aug 22 13:16:00 sshguard 40315 Exiting on signal. Aug 22 13:10:00 sshguard 40315 Now monitoring attacks. Aug 22 13:10:00 sshguard 33853 Exiting on signal. Aug 22 13:04:00 sshguard 33853 Now monitoring attacks. Aug 22 13:04:00 sshguard 3459 Exiting on signal. Aug 22 12:58:00 sshguard 3459 Now monitoring attacks. Aug 22 12:58:00 sshguard 78835 Exiting on signal.
Updated by Danilo Zrenjanin 3 months ago
- Status changed from Resolved to Feedback
Updated by Danilo Zrenjanin 3 months ago
- Status changed from Feedback to Resolved
Upon testing against the latest development build, I could not replicate the reported issue. Therefore, I am marking this ticket as resolved.
Updated by Jim Pingle about 2 months ago
- Subject changed from sshguard spams the system log to Restarting the logging daemon during rotation also restarts ``sshguard``, leading to frequent log messages
Updated by Jim Pingle about 2 months ago
- Plus Target Version changed from 24.08 to 24.11