Project

General

Profile

Actions

Bug #12747

closed

Restarting the logging daemon during rotation also restarts ``sshguard``, leading to frequent log messages

Added by Steve Wheeler almost 3 years ago. Updated about 2 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Logging
Target version:
Start date:
Due date:
% Done:

100%

Estimated time:
Plus Target Version:
24.11
Release Notes:
Default
Affected Version:
2.6.0
Affected Architecture:
All

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

clipboard-202204221938-uajpw.png (9.84 KB) clipboard-202204221938-uajpw.png Marle Cua-chin, 04/22/2022 06:38 AM
clipboard-202206300621-7gjov.png (135 KB) clipboard-202206300621-7gjov.png Franck Ck, 06/30/2022 05:21 AM
clipboard-202309230719-waesz.png (85.5 KB) clipboard-202309230719-waesz.png Jonathan Stafford, 09/23/2023 11:19 AM
clipboard-202309230720-yhwfb.png (21.2 KB) clipboard-202309230720-yhwfb.png Jonathan Stafford, 09/23/2023 11:20 AM
Actions #1

Updated by Viktor Gurov almost 3 years ago

it seems to be related to #12833

Actions #2

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.
Actions #3

Updated by Car F over 2 years ago

Having the same issue since 2.6.0.

Actions #4

Updated by Michael TRVL ALBT over 2 years ago

Having the same issue since 2.6.0 too.

Actions #5

Updated by Marle Cua-chin over 2 years ago

I'm also experiencing the same issue on 2.6.0

Actions #6

Updated by Antonio Pesce over 2 years ago

I'm having the same issue on 2.6.0 on 6 pfSense instance.

Actions #8

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.

Actions #9

Updated by Hayden Hill over 2 years ago

I am having the same issue in 22.05.

Actions #10

Updated by van trung tran almost 2 years ago

I am having the same issue in 22.05. Netgate XG1541

Actions #11

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

Actions #12

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.

Actions #13

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.

Actions #14

Updated by Jonathan Stafford about 1 year ago

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 :)

Actions #15

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.log
rw------ 1 root wheel 102682474 Jul 13 16:16 filter.log.0
rw------ 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

Actions #16

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.

Actions #17

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)

Actions #18

Updated by Marcos M 4 months ago

  • Subject changed from System log is filled by sshguard to sshguard spams the system log
  • Status changed from New to Ready To Test

Here's a patch for 24.03 for testing:

Apply then reboot.

Actions #19

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.

Actions #20

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

Actions #21

Updated by Marcos M 3 months ago

  • % Done changed from 0 to 100
Actions #22

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.
Actions #23

Updated by Danilo Zrenjanin 3 months ago

  • Status changed from Resolved to Feedback
Actions #24

Updated by Marcos M 3 months ago

Make sure to reboot after applying the patches.

Actions #25

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.

Actions #26

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
Actions #27

Updated by Jim Pingle about 2 months ago

  • Plus Target Version changed from 24.08 to 24.11
Actions

Also available in: Atom PDF