I have read the wiki. And dug through the issues on github. And googled to
ad nauseum.
Issue: F2B fails, but does not ban. This system has just worked for eight
years. For some weird reason, it quit working a few weeks ago. The problem
appears to be time related, but I cannot seem to scare it out. At the end
of the details below are several lines showing the time retrieved from the
hardware clock, the OS clock, and F2B. All of them seem to agree. The
timestamps in the log being scanned match these as well (see below).
I'm probably missing something really obvious, but I can't see the forest
for the trees at this point. Any help would be appreciated.
Here are the details.
OS:
Distributor ID: CentOS
Description: CentOS release 5.8 (Final)
Release: 5.8
Codename: Final
F2B:
:~# fail2ban-server --version
Fail2Ban v0.8.7
Its old, and I'm stuck with it due to client requirements.
Evidently we are matching....
:/etc/fail2ban# fail2ban-client status asterisk-udp
Status for the jail: asterisk-udp
|- filter
| |- File list: /var/log/asterisk/fail2ban
| |- Currently failed: 12
| `- Total failed: 452
`- action
|- Currently banned: 0
| `- IP list:
`- Total banned: 0
The jail configuration is the package configuration with maxretry changed
to 1 rather than 10.
1. The jail loads fine:
:~# fail2ban-client -d | grep "asterisk" | grep -E
"'((add)?(logpath|journalmatch)|start|add)'"
['add', 'asterisk-udp', 'auto']
['set', 'asterisk-udp', 'addlogpath', '/var/log/asterisk/fail2ban']
['add', 'asterisk-tcp', 'auto']
['set', 'asterisk-tcp', 'addlogpath', '/var/log/asterisk/fail2ban']
['start', 'asterisk-udp']
['start', 'asterisk-tcp']
2. The filter works fine:
:~# fail2ban-regex ./sample-log.txt /etc/fail2ban/filter.d/asterisk.conf
Running tests
=============
Use regex file : /etc/fail2ban/filter.d/asterisk.conf
Use log file : ./sample-log.txt
Results
=======
Failregex: 14 total
|- #) [# of hits] regular expression
| 2) [6] NOTICE.* .*: Registration from '.*' failed for '<HOST>:.*' - No
matching peer found
| 17) [2] NOTICE.* .*: "Anonymous peer IP: <HOST>
| 20) [6] SECURITY.*
SecurityEvent="InvalidAccountID".*RemoteAddress=".+?/.+?/<HOST>/.+?".*
`-
Ignoreregex: 0 total
Summary
=======
Addresses found:
[2]
156.96.113.252 (Mon Apr 27 12:57:58 2020)
156.96.113.252 (Mon Apr 27 12:57:58 2020)
156.96.113.252 (Mon Apr 27 12:58:03 2020)
156.96.113.252 (Mon Apr 27 12:58:03 2020)
156.96.113.252 (Mon Apr 27 12:58:22 2020)
156.96.113.252 (Mon Apr 27 12:58:22 2020)
[17]
156.96.118.133 (Mon Apr 27 12:58:04 2020)
198.46.135.250 (Mon Apr 27 12:58:26 2020)
[20]
156.96.113.252 (Mon Apr 27 12:57:58 2020)
156.96.113.252 (Mon Apr 27 12:57:58 2020)
156.96.113.252 (Mon Apr 27 12:58:03 2020)
156.96.113.252 (Mon Apr 27 12:58:03 2020)
156.96.113.252 (Mon Apr 27 12:58:22 2020)
156.96.113.252 (Mon Apr 27 12:58:22 2020)
Date template hits:
344 hit(s): Year-Month-Day Hour:Minute:Second
Success, the total number of match is 14
However, look at the above section 'Running tests' which could contain
important
information.
3. Sample segment of /var/log/asterisk/fail2ban (lightly sanitized):
[2020-04-27 12:57:58] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:63503' - No
matching peer found
[2020-04-27 12:57:58] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006678-800587",Severity="Error",Service="SIP",EventVersion="1",AccountID="94001",SessionID="0x2aaaaccbb0f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/63503"
[2020-04-27 12:57:58] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:63503' - No
matching peer found
[2020-04-27 12:57:58] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006678-840762",Severity="Error",Service="SIP",EventVersion="1",AccountID="94001",SessionID="0x2aaaaccbb0f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/63503"
[2020-04-27 12:58:00] NOTICE[32356] chan_sip.c: Peer '126' is now
UNREACHABLE! Last qualify: 1
[2020-04-27 12:58:03] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:51392' - No
matching peer found
[2020-04-27 12:58:03] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006683-419918",Severity="Error",Service="SIP",EventVersion="1",AccountID="36002",SessionID="0x2aaaacc741f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/51392"
[2020-04-27 12:58:03] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:51392' - No
matching peer found
[2020-04-27 12:58:03] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006683-447059",Severity="Error",Service="SIP",EventVersion="1",AccountID="36002",SessionID="0x2aaaacc741f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/51392"
[2020-04-27 12:58:04] NOTICE[10880] Ext. 011442037695879: "Anonymous peer
IP: 156.96.118.133"
[2020-04-27 12:58:22] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:52086' - No
matching peer found
[2020-04-27 12:58:22] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006702-102052",Severity="Error",Service="SIP",EventVersion="1",AccountID="5503",SessionID="0x2aaaaf4b58f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/52086"
[2020-04-27 12:58:22] NOTICE[32356] chan_sip.c: Registration from
'<sip:[email protected]>' failed for '156.96.113.252:52086' - No
matching peer found
[2020-04-27 12:58:22] SECURITY[32341] res_security_log.c:
SecurityEvent="InvalidAccountID",EventTV="1588006702-141975",Severity="Error",Service="SIP",EventVersion="1",AccountID="5503",SessionID="0x2aaaaf4b58f8",LocalAddress="IPV4/UDP/aaa.bbb.ccc.ddd/5060",RemoteAddress="IPV4/UDP/
156.96.113.252/52086"
[2020-04-27 12:58:26] NOTICE[10932] Ext. 0001546812410305: "Anonymous peer
IP: 198.46.135.250"
4. Sample of /var/log/fail2ban.log covering the same entries:
:~# tail -f /var/log/fail2ban.log
2020-04-27 12:57:58,830 fail2ban.filter : DEBUG Ignore line since time
1588006077.0 < 1588006678.83 - 600
2020-04-27 12:57:58,831 fail2ban.filter : DEBUG Processing line with
time:1588006078.0 and ip:156.96.113.252
2020-04-27 12:57:58,831 fail2ban.filter : DEBUG Ignore line since time
1588006078.0 < 1588006678.83 - 600
2020-04-27 12:57:58,831 fail2ban.filter : DEBUG Processing line with
time:1588006078.0 and ip:156.96.113.252
2020-04-27 12:57:58,831 fail2ban.filter : DEBUG Ignore line since time
1588006078.0 < 1588006678.83 - 600
2020-04-27 12:57:58,832 fail2ban.filter : DEBUG Processing line with
time:1588006078.0 and ip:156.96.113.252
2020-04-27 12:57:58,832 fail2ban.filter : DEBUG Ignore line since time
1588006078.0 < 1588006678.83 - 600
2020-04-27 12:57:58,832 fail2ban.filter : DEBUG Processing line with
time:1588006078.0 and ip:156.96.113.252
2020-04-27 12:57:58,833 fail2ban.filter : DEBUG Ignore line since time
1588006078.0 < 1588006678.83 - 600
2020-04-27 12:57:58,833 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,854 fail2ban.filter : DEBUG Found 156.96.113.252
2020-04-27 12:58:14,854 fail2ban.filter : DEBUG Currently have failures
from 13 IPs: [u'45.125.66.22', u'161.35.109.98', u'77.247.109.5',
u'37.49.229.190', u'51.158.30.15', u'208.46.183.250', u'198.46.135.250',
u'37.49.229.181', u'156.96.118.133', u'62.233.65.111', u'45.151.254.234',
u'163.172.226.61', u'156.96.113.252']
2020-04-27 12:58:14,855 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,855 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,855 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,856 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,856 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,856 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,857 fail2ban.filter : DEBUG Processing line with
time:1588006089.0 and ip:156.96.118.133
2020-04-27 12:58:14,857 fail2ban.filter : DEBUG Ignore line since time
1588006089.0 < 1588006694.86 - 600
2020-04-27 12:58:14,857 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:14,858 fail2ban.filter : DEBUG Found 156.96.113.252
2020-04-27 12:58:14,858 fail2ban.filter : DEBUG Currently have failures
from 13 IPs: [u'45.125.66.22', u'161.35.109.98', u'77.247.109.5',
u'62.233.65.111', u'51.158.30.15', u'208.46.183.250', u'198.46.135.250',
u'37.49.229.181', u'156.96.118.133', u'37.49.229.190', u'45.151.254.234',
u'163.172.226.61', u'156.96.113.252']
2020-04-27 12:58:14,859 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,859 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,860 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,860 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,860 fail2ban.filter : DEBUG Processing line with
time:1588006085.0 and ip:156.96.113.252
2020-04-27 12:58:14,860 fail2ban.filter : DEBUG Ignore line since time
1588006085.0 < 1588006694.86 - 600
2020-04-27 12:58:14,861 fail2ban.filter : DEBUG Processing line with
time:1588006089.0 and ip:156.96.118.133
2020-04-27 12:58:14,861 fail2ban.filter : DEBUG Ignore line since time
1588006089.0 < 1588006694.86 - 600
2020-04-27 12:58:14,861 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,879 fail2ban.filter : DEBUG Found 156.96.113.252
2020-04-27 12:58:30,879 fail2ban.filter : DEBUG Currently have failures
from 13 IPs: [u'45.125.66.22', u'161.35.109.98', u'77.247.109.5',
u'37.49.229.190', u'51.158.30.15', u'208.46.183.250', u'198.46.135.250',
u'37.49.229.181', u'156.96.118.133', u'62.233.65.111', u'45.151.254.234',
u'163.172.226.61', u'156.96.113.252']
2020-04-27 12:58:30,880 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,880 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.88 - 600
2020-04-27 12:58:30,881 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,881 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.88 - 600
2020-04-27 12:58:30,881 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,881 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.88 - 600
2020-04-27 12:58:30,882 fail2ban.filter : DEBUG Processing line with
time:1588006119.0 and ip:156.96.118.133
2020-04-27 12:58:30,883 fail2ban.filter : DEBUG Found 156.96.113.252
2020-04-27 12:58:30,883 fail2ban.filter : DEBUG Currently have failures
from 13 IPs: [u'45.125.66.22', u'161.35.109.98', u'77.247.109.5',
u'62.233.65.111', u'51.158.30.15', u'208.46.183.250', u'198.46.135.250',
u'37.49.229.181', u'156.96.118.133', u'37.49.229.190', u'45.151.254.234',
u'163.172.226.61', u'156.96.113.252']
2020-04-27 12:58:30,884 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,884 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.88 - 600
2020-04-27 12:58:30,884 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,885 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.89 - 600
2020-04-27 12:58:30,885 fail2ban.filter : DEBUG Processing line with
time:1588006101.0 and ip:156.96.113.252
2020-04-27 12:58:30,885 fail2ban.filter : DEBUG Ignore line since time
1588006101.0 < 1588006710.89 - 600
2020-04-27 12:58:30,886 fail2ban.filter : DEBUG Processing line with
time:1588006119.0 and ip:156.96.118.133
5. Hardware, OS, and F2B time on the server:
:/usr/share/fail2ban/server# hwclock && date && date +%s && python
timeTest.py
Mon 27 Apr 2020 12:58:52 PM EDT -0.079355 seconds
Mon Apr 27 12:58:55 EDT 2020
1588006735
Current Unixtime: 1588006735.45
Current localtime: (2020, 4, 27, 12, 58, 55, 0, 118, 1)
NOTE: The first line is the hardware clock. The second is the OS clock. The
third is the OS clock in unixtime. The fourth is a call using
MyTime.unixtime from F2B. The last is a call using MyTime.localtime from
F2B.
_______________________________________________
Fail2ban-users mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/fail2ban-users
