Unexpected entries in fail2ban log

Dim_Git · October 14, 2021, 5:32am

OS type and version: CentOS Linux 7.9.2009
Webmin version: 1.981
Virtualmin version: 6.17

Hi everyone, hope you are all safe and well.

This morning I checked out the logs for Fail2Ban and saw nothing like what I would expect.

Usually the logs look like this

2021-10-12 05:57:02,294 fail2ban.filter [6801]: INFO [postfix-sasl] Found 136.144.41.87 - 2021-10-12 05:57:02
2021-10-12 05:57:12,284 fail2ban.filter [6801]: INFO [postfix-sasl] Found 195.133.40.83 - 2021-10-12 05:57:12
2021-10-12 05:59:38,219 fail2ban.filter [6801]: INFO [postfix-sasl] Found 37.0.11.114 - 2021-10-12 05:59:38
2021-10-12 06:00:05,217 fail2ban.filter [6801]: INFO [sshd] Found 212.193.30.32 - 2021-10-12 06:00:05
2021-10-12 06:00:07,411 fail2ban.filter [6801]: INFO [sshd] Found 212.193.30.32 - 2021-10-12 06:00:07
2021-10-12 06:01:05,482 fail2ban.filter [6801]: INFO [postfix-sasl] Found 31.210.21.220 - 2021-10-12 06:01:05
2021-10-12 06:01:43,743 fail2ban.filter [6801]: INFO [postfix-sasl] Found 203.159.80.60 - 2021-10-12 06:01:43
2021-10-12 06:04:35,648 fail2ban.filter [6801]: INFO [postfix-sasl] Found 37.0.10.49 - 2021-10-12 06:04:35
2021-10-12 06:04:48,863 fail2ban.actions [6801]: NOTICE [sshd] Unban 212.193.30.101

But I also see this and loads of it

Oct 12 06:56:27 xvm136595 kernel: Linux version 4.18.13-1.el7.elrepo.x86_64 (mockbuild@Build64R7) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-28) (GCC)) #1 SMP Wed Oct 10 15:37:55 EDT 2018
Oct 12 06:56:27 xvm136595 kernel: Command line: root=/dev/xvda ro selinux=0 console=tty1 console=hvc0
Oct 12 06:56:27 xvm136595 kernel: x86/fpu: Supporting XSAVE feature 0x001: ‘x87 floating point registers’
Oct 12 06:56:27 xvm136595 kernel: x86/fpu: Supporting XSAVE feature 0x002: ‘SSE registers’
Oct 12 06:56:27 xvm136595 kernel: x86/fpu: Supporting XSAVE feature 0x004: ‘AVX registers’
Oct 12 06:56:27 xvm136595 kernel: x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
Oct 12 06:56:27 xvm136595 kernel: x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using ‘standard’ format.
Oct 12 06:56:27 xvm136595 kernel: BIOS-provided physical RAM map:
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009ffff] usable
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x00000000000a0000-0x00000000000fffff] reserved
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x0000000000100000-0x00000000fbffffff] usable
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x00000000fc000000-0x00000000fc00903f] ACPI data
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x00000000feff8000-0x00000000feffffff] reserved
Oct 12 06:56:27 xvm136595 kernel: BIOS-e820: [mem 0x0000000100000000-0x00000001040003ff] usable
Oct 12 06:56:27 xvm136595 kernel: NX (Execute Disable) protection: active
Oct 12 06:56:27 xvm136595 kernel: DMI not present or invalid.

and

Oct 12 06:56:31 xvm136595 systemd: Closed udev Control Socket.
Oct 12 06:56:31 xvm136595 systemd: Stopping udev Control Socket.
Oct 12 06:56:31 xvm136595 systemd: Closed udev Kernel Socket.
Oct 12 06:56:31 xvm136595 systemd: Stopping udev Kernel Socket.
Oct 12 06:56:31 xvm136595 systemd: Starting Cleanup udevd DB…
Oct 12 06:56:31 xvm136595 systemd: Started Cleanup udevd DB.
Oct 12 06:56:31 xvm136595 systemd: Reached target Switch Root.
Oct 12 06:56:31 xvm136595 systemd: Starting Switch Root.
Oct 12 06:56:31 xvm136595 systemd: Starting Switch Root…
Oct 12 06:56:31 xvm136595 systemd: Switching root.
Oct 12 06:56:31 xvm136595 journal: Journal stopped
Oct 12 06:56:32 xvm136595 journal: Runtime journal is using 8.0M (max allowed 165.9M, trying to leave 248.8M free of 1.6G available → current limit 165.9M).
Oct 12 06:56:32 xvm136595 systemd-journald[349]: Received SIGTERM from PID 1 (systemd).
Oct 12 06:56:32 xvm136595 kernel: systemd: 30 output lines suppressed due to ratelimiting
Oct 12 06:56:32 xvm136595 systemd[1]: Inserted module ‘ip_tables’
Oct 12 06:56:32 xvm136595 journal: Journal started

and

Oct 12 08:28:19 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#49193: received notify for zone ‘localhost’
Oct 12 08:28:19 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#34998: received notify for zone ‘1.0.0.127.in-addr.arpa’
Oct 12 08:28:19 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#34998: received notify for zone ‘0.in-addr.arpa’
Oct 12 08:28:19 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#34998: received notify for zone ‘localhost.localdomain’
Oct 12 08:28:19 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#34998: received notify for zone ‘1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa’
Oct 12 08:28:22 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#37515: received notify for zone ‘localhost.localdomain’
Oct 12 08:28:23 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#43576: received notify for zone ‘localhost’
Oct 12 08:28:23 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#43576: received notify for zone ‘1.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.ip6.arpa’
Oct 12 08:28:23 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#43576: received notify for zone ‘1.0.0.127.in-addr.arpa’
Oct 12 08:28:23 xvm136595 named[15268]: client @0x7f4f1c0c6370 85.234.151.55#43576: received notify for zone ‘0.in-addr.arpa’
O

The above are just a few snips of the log and there is much much more.

This server is acting as a slave nameserver ONLY no sites are hosted on it.

I’m not suggesting that I want the lines analysed just should these lines be in the fail2ban logs?

I have thought that these logs should not be in the fail2ban log but elsewhere so I have dug around looking for some clue like the wrong log specified somewhere but could find nothing that looked hinkey or out of place. Can anybody confirm that the above are expected or otherwise please.

Edited to add - This looks like it started yesterday (server up and running for about 2 weeks) and may have followed a reboot but not certain of that.

Further edit to add - I see the following sample lines in the logs

/var/log/maillog
Oct 14 07:08:43 xvm136595 postfix/smtpd[31629]: warning: unknown[31.210.20.48]: SASL LOGIN authentication failed: authentication failure

/var/log/fail2ban.log
Oct 14 07:08:43 xvm136595 postfix/smtpd[31629]: warning: unknown[31.210.20.48]: SASL LOGIN authentication failed: authentication failure

Thanks for reading.

Dim_Git · October 15, 2021, 6:51am

Well, I spent a few hours and I think I have found something. I need others with more experience to confirm that what I have done will not cause other issues further down the line.

I found a web page discussing logs which suggested (reading between the lines) that my issue might be in etc/rsyslog.conf. So I took a look and compared it to another server which was working ok. Here is what I found:

At the bottom of the file there was this (the beginning does not show here, should be star dot star)

. /var/log/fail2ban.log

On the server that I compared it to the last line was this

*.none|/var/log/fail2ban.log

So I edited the misbehaving one to this (commented out the original line for future reference)

.|/var/log/fail2ban.log

*.none|/var/log/fail2ban.log

Now the fail2ban logs seem to be normal again.

The only issue I now see is that on the System Logs page I see the fail2ban entry twice.

Log Destination Active? Messages selected
File /var/log/fail2ban.log No .
File /var/log/fail2ban.log Yes *.none

Since I commented out the original line in rsyslog.conf I guess my edit of that file is not responsible for this double entry.

So, that leaves me with a couple of questions

Am I storing up problems for later
If I delete the non-active entry in the view system logs page cause issues?

As you can see, I am trying very hard to resolve my issues but I do need a little help along the way so would be grateful for a little confirmation/guidance.

Thanks for reading.

Joe · October 15, 2021, 6:57am

I have no idea how you got there, so I don’t really have any advice. It’s not a problem I’ve seen, and I can’t think of how your config would end up that way. There’s no reason for syslog to go to the fail2ban log, and it’s not related to anything Virtualmin configures.

Joe · October 15, 2021, 7:10am

Oh, I bet I know what’s going on.

Did you “Add a new system log” in the System Logs module for fail2ban so you could view the log in Webmin? The UI here is probably not as clear as it should be…but that isn’t how you do that. You can add other logs to view in the UI, but it’s in the Module Configuration. The “Add a new system log” is for configuring syslog (rsyslog in this case). fail2ban doesn’t log through syslog in its normal configuration…if you add it to the syslog configuration, you’re telling syslog to write something to the fail2ban log (what it writes depends on configuration, but you don’t want syslog to write anything to the fail2ban log; fail2ban writes its own log).

Dim_Git · October 15, 2021, 7:12am

Hi Joe,
Thanks for that.

While you were replying I was editing to try to get my post to make sense but the forum will not allow star dot star in the text.

The fact that there are now two entries in the view logs page (Webmin>System>System Logs) and that has only appeared since I edited the rsyslog.conf file sound odd.

I will do some more investigation and report back.

Joe · October 15, 2021, 7:15am

There should be none.

If you want to view the fail2ban log in the System Logs module, add it in the Module Configuration under “Other log files to show (With optional descriptions)”. They’ll then show up, but not be clickable because they aren’t part of the syslog configuration; you’ll have a “View” button, though, as with Webmin and Usermin logs and some others that are shown by default.

Dim_Git · October 15, 2021, 9:14am

Problem solved, thanks for your input Joe.

I edited etc/rsyslog.conf back to where it was like:
star-dot-star /var/log/fail2ban.log
as the last line.

Rebooted and the fail2ban log showed log entries for things other than fail2ban logs.

Deleted the view logs entry for fail2ban in the system logs module (more on that below) and rebooted. Viewing the logs through file manager showed all logs as I would expect.

I used “Add a new system log” in the System Logs module for fail2ban (more below) and rebooted and all was still ok.

THEN I noticed the “Apply Changes” buton. Du’h!!!

Despite looking at this so many times I failed to spot that. I used the same method (“Add a new system log” in the System Logs module) for so many years on my old Centos5 boxes without issue so just continued to do so on the new boxes. Slap-on-the-wrist accepted and sorry for having been such a pain.

Thanks again.

Joe · October 15, 2021, 3:17pm

It’s possible to use the add button without leading to random crud in a log (either check “No” for “active”, or set it to log nothing to that log). But, the System Logs module is confusing. It’s not as apparent as it should be that it is literally a syslog module and using the add system log button adds more targets for syslog to log to. It’s kind of an accident of history that this is the most obvious way to view logs in Webmin and the UI never got updated to make it less confusing.

system · December 14, 2021, 3:18pm

This topic was automatically closed 60 days after the last reply. New replies are no longer allowed.