Tons sshguard log entries and its not enabled

jeff3820

An interesting observation...I have 2 weatherstations that are renewing their DHCP leases every MINUTE. Is there a way to not log those devices? I had them on a static IP but just took them off to see if that was an issue:

Feb 20 18:03:48 dhcpd 96898 DHCPACK on 192.168.40.63 to 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:48 dhcpd 96898 DHCPREQUEST for 192.168.40.63 (192.168.40.1) from 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:48 dhcpd 96898 reuse_lease: lease age 161 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.63
Feb 20 18:03:48 dhcpd 96898 DHCPOFFER on 192.168.40.63 to 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:48 dhcpd 96898 DHCPDISCOVER from 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:48 dhcpd 96898 reuse_lease: lease age 161 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.63
Feb 20 18:03:48 dhcpd 96898 DHCPACK on 192.168.40.64 to 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:48 dhcpd 96898 DHCPREQUEST for 192.168.40.64 (192.168.40.1) from 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:48 dhcpd 96898 reuse_lease: lease age 159 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.64
Feb 20 18:03:48 dhcpd 96898 DHCPOFFER on 192.168.40.64 to 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:48 dhcpd 96898 DHCPDISCOVER from 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:48 dhcpd 96898 reuse_lease: lease age 159 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.64
Feb 20 18:03:11 dhcpd 96898 DHCPACK on 192.168.40.63 to 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:11 dhcpd 96898 DHCPREQUEST for 192.168.40.63 (192.168.40.1) from 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:11 dhcpd 96898 reuse_lease: lease age 124 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.63
Feb 20 18:03:11 dhcpd 96898 DHCPOFFER on 192.168.40.63 to 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:11 dhcpd 96898 DHCPDISCOVER from 60:01:94:32:db:92 (ESP_32DB92) via em1.40
Feb 20 18:03:11 dhcpd 96898 reuse_lease: lease age 124 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.63
Feb 20 18:03:11 dhcpd 96898 DHCPACK on 192.168.40.64 to 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:11 dhcpd 96898 DHCPREQUEST for 192.168.40.64 (192.168.40.1) from 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:11 dhcpd 96898 reuse_lease: lease age 122 (secs) under 25% threshold, reply with unaltered, existing lease for 192.168.40.64
Feb 20 18:03:11 dhcpd 96898 DHCPOFFER on 192.168.40.64 to 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40
Feb 20 18:03:11 dhcpd 96898 DHCPDISCOVER from 2c:3a:e8:38:af:53 (ESP_38AF53) via em1.40

troysjanda

@jeff3820

id either extend the lease times or give them static ips, But I am a novice. Still learning myself

jeff3820

@johnpoz I upped the log size and I’ll monitor for now. I did isolate another logging issue that is specific to ESP WiFi/networking chips used in IOT devices. I have 2 WiFi weather stations in the house that are connected to my IOT VLAN. These devices that use the ESP chips and are so dumb that they don’t handle DHCP in the traditional manner. Regardless of when the DHCP server tells the client to renew their IP address, these clients renew their IP address EVERY MINUTE…and I have 2 of them. These devices are so crappy they get dropped by my Unifi access points after 1-2 hours. I use an old Asus router as an access point just to connect these devices. I’m sure this was the cause of much DHCP log rotation.

My solution was to make the Asus router a router again and shift weather station IP management to the Asus getting the noise off of Pfsense. Pfsense assigns the IP address to the Asus and I keep all of these devices in the IOT VLAN. Of course the best solution would be to toss these weather stations in the trash but this will work for now.

geovaneg

Hi,

PfSense CE 2.6.0

As a workaround I tried disabled the log packets matched from the default block rules in the ruleset to reduce the amount of system logs, but after a period of calm, the problem has returned.
I changed the log file size from 500K to 1024 and didn't work either. After about a day the logs became polluted again.
In my case, the filter logs are very large and i need them.
I haven't found a solution for this yet. This "dirt" in the logs can hinder the visibility of some critical event.

Jul 8 12:17:00 sshguard 27403 Exiting on signal.
Jul 8 12:17:00 sshguard 86043 Now monitoring attacks.
Jul 8 12:19:00 sshguard 86043 Exiting on signal.
Jul 8 12:19:00 sshguard 71802 Now monitoring attacks.
Jul 8 12:21:00 sshguard 71802 Exiting on signal.
Jul 8 12:21:00 sshguard 52201 Now monitoring attacks.
Jul 8 12:23:00 sshguard 52201 Exiting on signal.
Jul 8 12:23:00 sshguard 32915 Now monitoring attacks.
Jul 8 12:25:00 sshguard 32915 Exiting on signal.
Jul 8 12:25:00 sshguard 76907 Now monitoring attacks.
Jul 8 12:27:00 sshguard 76907 Exiting on signal.
Jul 8 12:27:00 sshguard 52340 Now monitoring attacks.

Geovane

johnpoz

@geovaneg your saying you have a log file rotating every 2 minutes? Yeah I could see how that would be problematic.

geovaneg

Hi @johnpoz

Yes:

[2.6.0-RELEASE][admin@pfsense]/var/log: ls -tal | grep filter
-rw------- 1 root wheel 585448 Jul 8 12:48 filter.log
-rw------- 1 root wheel 110227 Jul 8 12:47 filter.log.0.bz2
-rw------- 1 root wheel 77990 Jul 8 12:44 filter.log.1.bz2
-rw------- 1 root wheel 101983 Jul 8 12:42 filter.log.2.bz2
-rw------- 1 root wheel 78511 Jul 8 12:39 filter.log.3.bz2
-rw------- 1 root wheel 88127 Jul 8 12:37 filter.log.4.bz2
-rw------- 1 root wheel 109005 Jul 8 12:35 filter.log.5.bz2
-rw------- 1 root wheel 82652 Jul 8 12:32 filter.log.6.bz2

johnpoz

@geovaneg your going to need to limit how much your logging, or go with a much larger size log file.. maybe 10M vs 1, or even like 100M? That seems like a lot of logging ;)

geovaneg

thank you to reply @johnpoz

I found it strange that for some time after I change the settings (about a day) the problem stopped but returns later. Also, in previous versions the amount of logs was the same and the problem did not occur.

Do you have any idea why this change in behavior?

stephenw10

The logs switched from the circular log format back to the default BSD format. That means they have to be rotated and sshguard restarts whenever any log is rotated.
https://docs.netgate.com/pfsense/en/latest/releases/2-5-0.html?highlight=clog#logging

Steve

geovaneg

@stephenw10 said in Tons sshguard log entries and its not enabled:

sshguard

Thank you @stephenw10

I understood.

But the previous version of this server was already 2.5.1 and it didn't have the excess of sshguard logs, with the same volume of logs and I imagine with the same rotation frequency of them.

This is what struck me as strange.

johnpoz

@geovaneg can you not limit the stuff your logging in some way? And also up the log file size?

So at a 2 min rotation for 1M and only keeping what 6 rotations - the amount of logs is only the last 12 minutes anyway - how is that even useful?

edit: my math off, with current log and 6 rotated (0-6 = 7) at most you would have like 16 minutes ;)

edit2: none of what is being logged is noise that you could just not log? I would think you would want atleast 24 hours of logs? Mine go back like 3 days and only storing 5 rotations. Are you also sending to say syslog as well?

stephenw10

Yeah you should be using an external syslog server there.

In 2.5.1 the same applies so it can really only have been that the logs were not rotating. Eother the logs were far larger or there was far less to log.

Steve

geovaneg

@stephenw10

Hi Guys.

Yes, logs are sent to a remote syslog server.
This PfSense server serves a large wireless network and I need to retain the fw logs for possible future audits.
I still have 4 other VPN servers that I haven't updated to version 2.6.0. They are in 2.5.2. I must face the same problem with them as they produce a lot of logs.

I ran a test just now:
I manually reset the syslog, via graphical console: Status->Services->Syslogd<Restart Service>

Jul 8 15:21:59 pfsense syslogd: exiting on signal 15
Jul 8 15:21:59 pfsense syslogd: kernel boot file is /boot/kernel/kernel

We can see that the files keep rotating:

[2.6.0-RELEASE][admin@pfsense]/var/log: ls -tal | grep filter
-rw------- 1 root wheel 940974 Jul 8 15:35 filter.log
-rw------- 1 root wheel 116009 Jul 8 15:34 filter.log.0.bz2
-rw------- 1 root wheel 127082 Jul 8 15:32 filter.log.1.bz2
-rw------- 1 root wheel 114071 Jul 8 15:30 filter.log.2.bz2
-rw------- 1 root wheel 92094 Jul 8 15:28 filter.log.3.bz2
-rw------- 1 root wheel 101016 Jul 8 15:26 filter.log.4.bz2
-rw------- 1 root wheel 93269 Jul 8 15:24 filter.log.5.bz2
-rw------- 1 root wheel 103993 Jul 8 15:22 filter.log.6.bz2

However, there are no more "sshguard" messages in the system logs until I forced an event into the log (logout and login to the web interface), which seems to have "waked up" the problem again.:

Jul 8 15:18:00 sshguard 25670 Exiting on signal.
Jul 8 15:18:00 sshguard 10773 Now monitoring attacks.
Jul 8 15:20:00 sshguard 10773 Exiting on signal.
Jul 8 15:20:00 sshguard 95347 Now monitoring attacks.
Jul 8 15:21:59 syslogd exiting on signal 15
Jul 8 15:21:59 syslogd kernel boot file is /boot/kernel/kernel
Jul 8 15:27:45 nginx 2022/07/08 15:27:45 [error] 2540#100160: send() failed (54: Connection reset by peer)
Jul 8 15:40:28 php-fpm 89546 /index.php: User logged out for user 'admin' from: remote-machine (Local Database)
Jul 8 15:40:31 php-fpm 89546 /index.php: Successful login for user 'admin' from: remote-machine (Local Database)
Jul 8 15:40:31 sshguard 13794 Now monitoring attacks.
Jul 8 15:42:00 sshguard 13794 Exiting on signal.
Jul 8 15:42:00 sshguard 93750 Now monitoring attacks.
Jul 8 15:44:00 sshguard 93750 Exiting on signal.

Could you help me understand why manual reset interrupts sshguard log records for a while, even though there is rotation?

Thanks

stephenw10

Hmm, that looks more a bug in sshguard that stops it running....

stephenw10

Yeah, the processes should look like:

root    77695   0.0  0.1  11384  2824  -  Ss   13:03     0:00.24 |-- /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.p
root    63461   0.0  0.1  11524  3048  -  Is   20:41     0:00.00 | `-- /bin/sh /usr/local/sbin/sshguard -i /var/run/sshguard.pid
root    63916   0.0  0.1  10620  2224  -  I    20:41     0:00.00 |   |-- /bin/cat
root    63956   0.0  0.2  17420  4420  -  IC   20:41     0:00.00 |   |-- /usr/local/libexec/sshg-parser
root    64030   0.0  0.1  12072  2796  -  IC   20:41     0:00.00 |   |-- /usr/local/libexec/sshg-blocker
root    64102   0.0  0.2  11524  3052  -  I    20:41     0:00.00 |   `-- /bin/sh /usr/local/sbin/sshguard -i /var/run/sshguard.pid
root    64566   0.0  0.1  11492  3044  -  I    20:41     0:00.00 |     `-- /bin/sh /usr/local/libexec/sshg-fw-pf

But after restarting syslogd manually:

root    38082   0.0  0.1  11372  2820  -  Ss   20:44     0:00.00 |-- /usr/sbin/syslogd -s -c -c -l /var/dhcpd/var/run/log -P /var/run/syslog.pid -f /etc/syslog.conf

And logging out and back in restarts it:

Jul 8 20:49:47 	sshd 	77257 	Received disconnect from 172.21.16.5 port 58362:11: disconnected by user
Jul 8 20:49:47 	sshd 	77257 	Disconnected from user admin 172.21.16.5 port 58362
Jul 8 20:49:47 	sshguard 	26522 	Now monitoring attacks.
Jul 8 20:49:52 	sshd 	27315 	Accepted keyboard-interactive/pam for admin from 172.21.16.5 port 58364 ssh2

Hmm

stephenw10

Ok, it's not really a bug because the process is restarted as soon as there is a login attempt. And it still locks you out after three bad attempts.

johnpoz

@stephenw10 you could even call it a feature ;)

Why run a process if there is nothing to do.. Until there is a login attempt why monitor a log for something that isn't happening ;)

stephenw10

Mmm, but that begs the question, why run it continually at all?

geovaneg

@johnpoz

Following this line of reasoning, I wonder: is it really necessary for sshguard to keep recording in the system log each time it restarts along with rotate, if it is really protecting the ssh service?
Is there another unwanted side effect of the rotate occurring every 2 minutes? It wouldn't matter much to me, as long as it doesn't fill up my filesystem, as the logs are sent remotely.
Isn't there a way to disable sshguard restart log in the system logs?

geovaneg

@stephenw10 said in Tons sshguard log entries and its not enabled:

Mmm, but that begs the question, why run it continually at all?

exactly!