Short story: This turned out to be symptomatic of a missing intranet route in the route table on this server.
I had a user notify me of a time sync error on his Win10 machine. While it initially seemd totally unrelated, since the server running F2B is also the time server for the network, I took a look. All throughout the process of troubleshooting the F2B issue, the server claimed it was in sync to the external ntp servers used as sources. All of the time related checks I had done seemed to support that (as seen in my original post). The problem with the Win10 client turned out to be due to a missing route in the route table on the server in question. When I reinstated that route, the Win10 client successfully sync'd and F2B immediately began banning addresses again. My best explanation for this phenomena is this: Prior to discovering the missing route, I noticed that there was elevated latency on both links to the server. But only to the tune of about 30 ms longer than normal. That led me to look at the routing table. After reinstating the route, the latencies returned to normal for those links. While troubleshooting the F2B problem, I noticed that the timestamps appeared to differ by almost a second (830 ms, 860 ms, etc.). I mistakenly thought that F2B would consider that difference "noise." Apparently that is not so. I think that the network latency may have been skewing the ntp sync enough to introduce the few ms offset. However, I am no network time guru, so I really have no idea. In response to the assistance kindly provided by Robert: I had not seen that thread and the issue described appears similar to mine. Different backends were not an option for me. This system is a bit broken and is slated for an upgrade this summer. Thanks for letting me bounce this off of the list, and thanks very much for an excellent application which just keeps on working! Kind regards, Chris On Mon, Apr 27, 2020 at 4:09 PM Robert Kudyba <[email protected]> wrote: > Have you tried some of the suggestions posted at this github thread? > https://github.com/fail2ban/fail2ban/issues/1986 > > Can you try different backend options? Or use HEAVYDEBUG for logging > (which will cause a lot more logs so just for a bit) > > >> Date: Mon, 27 Apr 2020 13:42:18 -0400 >> From: Christopher Nighswonger <[email protected]> >> To: [email protected] >> Subject: [Fail2ban-users] F2B not banning >> Message-ID: >> <CAA7=B8wPgR-aXSaNeuH58g-e4d8eLb6JM33n9T= >> [email protected]> >> Content-Type: text/plain; charset="utf-8" >> >> 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. >> -------------- next part -------------- >> An HTML attachment was scrubbed... >> >> ------------------------------ >> >> >> >> ------------------------------ >> >> Subject: Digest Footer >> >> _______________________________________________ >> Fail2ban-users mailing list >> [email protected] >> >> https://urldefense.proofpoint.com/v2/url?u=https-3A__lists.sourceforge.net_lists_listinfo_fail2ban-2Dusers&d=DwICAg&c=aqMfXOEvEJQh2iQMCb7Wy8l0sPnURkcqADc2guUW8IM&r=X0jL9y0sL4r4iU_qVtR3lLNo4tOL1ry_m7-psV3GejY&m=yI-ZX3RYAturTEq_-uPrMwSEWTI4N0jtcPUouCX-Mco&s=PwrI-MdLH5Wa7akG7B4Xk8Aydl9usDtmQe8b0EA_N7s&e= >> >> >> ------------------------------ >> >> End of Fail2ban-users Digest, Vol 161, Issue 12 >> *********************************************** >> > _______________________________________________ > Fail2ban-users mailing list > [email protected] > https://lists.sourceforge.net/lists/listinfo/fail2ban-users >
_______________________________________________ Fail2ban-users mailing list [email protected] https://lists.sourceforge.net/lists/listinfo/fail2ban-users
