Logging issue?

[Guus Teley]

On FreeBSD 14, SSHGuard 2.4.3_2,1, giving the command:

 grep -i "SASL LOGIN authentication failed:" /var/log/maillog | grep 80.244.11| wc -l

it returns 2303 hits for today.

When given the command:

 grep -i postfix /var/log/auth.log

it returns nothing. Also:

grep -i postfix /var/log/message

gives one hit for today, but not containing the mentioned subnet:

Jun 3 01:04:17 <hostname> sshguard[1377]: Attack from "207.90.244.2" on service Postfix with danger 10.

But: Checking the SSHGuard block-list in PF returns:

 pfctl -T show -t sshguard | grep 80.244.11

80.244.11.0/24

Correctly showing the entire /24 subnet being blocked.

Now my questions are:

• Why are there 2303 attempts to intrude my system before SSHGuard blocked the malicious attackers subnet?
• Why aren’t there any messages in the Auth.log and messages logfiles stating the login attempts?

‌

‌

[Kevin Zheng]

Thanks for the report.

1. Login attempts via postfix may only be logged in /var/log/maillog. Could you show your sshguard.conf? It probably already has /var/log/maillog specified as one of the files it should monitor.

2. Look for log messages coming from "sshguard", e.g. "Attack from..." and note the time stamp, comparing with the time stamps from your mail log. This may provide clues as to what is happening.

3. Verify your pf.conf. Are your firewall rules actually blocking the attackers in the table?

[Guus Teley]

Hi Kevin.

sshguard.conf (the important part):

BACKEND="/usr/local/libexec/sshg-fw-pf"

FILES="/var/log/auth.log /var/log/maillog"
IPV6_SUBNET=64
IPV4_SUBNET=24

As I mentioned, the ‘attack from’ messages appear in /var/log/messages and ‘SASL login failure’ in /var/log/maillog.
The attackers subnet is being blocked by sshguard, as shown in the output of pfctl -t sshguard -T show

My question is why there are so many attacks logged into the maillog file before sshguard blocks the offender?
Or could it be that the offender was blocked because he also tried to get in via SSH? (And that the maillog file actually was ignored)

[Kevin Zheng]

Can you post an example of entry from maillog that shows the message that should be recognized as an attack, but you think isn’t?

You can check this yourself with the command given in the TROUBLESHOOTING section (“Is SSHGuard recognizing attacks?”) in the sshguard-setup(7) man page.

[Guus Teley]

Hello Kevin,

Here’s an excerpt from a host, given the command “cat /var/log/maillog | /usr/local/libexec/sshg-parser -a” :

• Jun 10 15:29:07 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.62]: SASL LOGIN authentication failed: authentication failure, sasl_username=rma
• Jun 10 15:29:08 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.62]
  Jun 10 15:29:08 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.62] ehlo=1 auth=0/1 rset=1 commands=2/3
• Jun 10 15:29:11 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.122]: SASL LOGIN authentication failed: authentication failure, sasl_username=neg
• Jun 10 15:29:12 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.122]
  Jun 10 15:29:12 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.122] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:29:16 <host> postfix/smtps/smtpd[38387]: connect from unknown[80.244.11.151]
  Jun 10 15:29:16 <host> postfix/smtps/smtpd[38387]: Anonymous TLS connection established from unknown[80.244.11.151]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:29:18 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.151]: SASL LOGIN authentication failed: authentication failure, sasl_username=news2
• Jun 10 15:29:18 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.151]
  Jun 10 15:29:18 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.151] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:29:21 <host> postfix/smtps/smtpd[38242]: connect from unknown[80.244.11.131]
  Jun 10 15:29:23 <host> postfix/smtps/smtpd[38242]: Anonymous TLS connection established from unknown[80.244.11.131]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:29:32 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.131]: SASL LOGIN authentication failed: authentication failure, sasl_username=praise
• Jun 10 15:29:33 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.131]
  Jun 10 15:29:33 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.131] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:29:53 <host> postfix/smtps/smtpd[38387]: connect from unknown[80.244.11.66]
  Jun 10 15:29:53 <host> postfix/smtps/smtpd[38387]: Anonymous TLS connection established from unknown[80.244.11.66]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:29:56 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.66]: SASL LOGIN authentication failed: authentication failure, sasl_username=subaru
• Jun 10 15:29:56 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.66]
  Jun 10 15:29:56 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.66] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:30:11 <host> postfix/smtps/smtpd[38242]: connect from unknown[80.244.11.65]
  Jun 10 15:30:11 <host> postfix/smtps/smtpd[38387]: connect from unknown[80.244.11.92]
  Jun 10 15:30:11 <host> postfix/smtps/smtpd[38242]: Anonymous TLS connection established from unknown[80.244.11.65]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
  Jun 10 15:30:12 <host> postfix/smtps/smtpd[38387]: Anonymous TLS connection established from unknown[80.244.11.92]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:30:15 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.65]: SASL LOGIN authentication failed: authentication failure, sasl_username=startup
• Jun 10 15:30:16 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.65]
  Jun 10 15:30:16 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.65] ehlo=1 auth=0/1 rset=1 commands=2/3
• Jun 10 15:30:16 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.92]: SASL LOGIN authentication failed: authentication failure, sasl_username=mem
• Jun 10 15:30:17 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.92]
  Jun 10 15:30:17 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.92] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:30:40 <host> postfix/smtps/smtpd[38242]: connect from unknown[80.244.11.60]
  Jun 10 15:30:40 <host> postfix/smtps/smtpd[38242]: Anonymous TLS connection established from unknown[80.244.11.60]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:30:42 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.60]: SASL LOGIN authentication failed: authentication failure, sasl_username=quser
• Jun 10 15:30:42 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.60]
  Jun 10 15:30:42 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.60] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:31:12 <host> postfix/smtps/smtpd[38387]: connect from unknown[80.244.11.148]
  Jun 10 15:31:13 <host> postfix/smtps/smtpd[38387]: Anonymous TLS connection established from unknown[80.244.11.148]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
  Jun 10 15:31:13 <host> postfix/smtps/smtpd[38242]: connect from unknown[80.244.11.140]
  Jun 10 15:31:14 <host> postfix/smtps/smtpd[38242]: Anonymous TLS connection established from unknown[80.244.11.140]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:31:15 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.148]: SASL LOGIN authentication failed: authentication failure, sasl_username=letina
• Jun 10 15:31:15 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.148]
  Jun 10 15:31:15 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.148] ehlo=1 auth=0/1 rset=1 commands=2/3
• Jun 10 15:31:16 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.140]: SASL LOGIN authentication failed: authentication failure, sasl_username=margret
• Jun 10 15:31:17 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.140]
  Jun 10 15:31:17 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.140] ehlo=1 auth=0/1 rset=1 commands=2/3
  Jun 10 15:31:26 <host> postfix/smtps/smtpd[38387]: connect from unknown[80.244.11.82]
  Jun 10 15:31:27 <host> postfix/smtps/smtpd[38387]: Anonymous TLS connection established from unknown[80.244.11.82]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
  Jun 10 15:31:30 <host> postfix/smtps/smtpd[38242]: connect from unknown[80.244.11.64]
  Jun 10 15:31:31 <host> postfix/smtps/smtpd[38242]: Anonymous TLS connection established from unknown[80.244.11.64]: TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)
• Jun 10 15:31:32 <host> postfix/smtps/smtpd[38242]: warning: unknown[80.244.11.64]: SASL LOGIN authentication failed: authentication failure, sasl_username=mail.ns1
• Jun 10 15:31:32 <host> postfix/smtps/smtpd[38242]: lost connection after AUTH from unknown[80.244.11.64]
  Jun 10 15:31:32 <host> postfix/smtps/smtpd[38242]: disconnect from unknown[80.244.11.64] ehlo=1 auth=0/1 rset=1 commands=2/3
• Jun 10 15:31:34 <host> postfix/smtps/smtpd[38387]: warning: unknown[80.244.11.82]: SASL LOGIN authentication failed: authentication failure, sasl_username=oldPassword
• Jun 10 15:31:36 <host> postfix/smtps/smtpd[38387]: lost connection after AUTH from unknown[80.244.11.82]
  Jun 10 15:31:36 <host> postfix/smtps/smtpd[38387]: disconnect from unknown[80.244.11.82] ehlo=1 auth=0/1 rset=1 commands=2/3

As you can see, the parser does recognize them as an attack.

Given the command :

grep -i "SASL login" /var/log/maillog | grep 80.244.11 | wc -l

it returns 2583.
This means there were 2583 attempts to breach security form the given subnet.
But why wasn’t the culprit shut down after some attempts?

Given the command:

pfctl -T show -t sshguard | grep 80.244.11

it shows the offending subnet has been blocked (it shows 80.244.11.0/24)

So the question remains: Why doesn't SSHGuard block the attacker right away, allowing it to continue endlessly?
Because, if it had been blocked right away, it wouldn't be possible to log 2583 attempts in the maillog file.

To me it seems as if the culprit got blocked for some other action, although I can’t find a matching entry for this subnet in the auth.log file.

‌

[Guus Teley]

And I just notice that, although pfctl shows the subnet has been blocked, the messages in the maillog file keep coming up (current 2636)

[Guus Teley]

To be sure, here’s the part of my pf rules file that handles sshguard:

table <BadGuys> persist file "/usr/local/etc/pf_badguys"
table <sshguard> persist
scrub in all
nat pass on $ext_if from $jail_net to any -> $ext_address
block in on $ext_if from <sshguard> to any label "ssh bruteforce"
block in on $ext_if from <BadGuys> to any label "Block BadGuys"
block in all

‌