Fail2ban: Fail2ban does not detect custom ssh filter

[Madh93]

Environment:

• Fail2Ban version (including any possible distribution suffixes): 0.9.3
• OS, including release name/version: Ubuntu 16.04.4 LTS
• [x] Fail2Ban installed via OS/distribution mechanisms
• [x] You have not applied any additional foreign patches to the codebase
• [ ] Some customizations were done to the configuration (provide details below is so)

The issue:

I have added a custom filter file to detect Invalid user XXXX from x.x.x.x but Fail2ban does not detect custom ssh filter.

Steps to reproduce

Connect from a remote host using an invalid user.

Expected behavior

Fail2ban's log should show Found x.x.x.x and finally after 2 retries Ban x.x.x.x too.

Observed behavior

Fail2ban's log does not show the expected entries.

Failban-regex results

For a simple entry:

ln="Apr 15 10:55:39 fail2ban sshd[8636]: Invalid user random from 189.166.145.133"
fail2ban-regex "$ln" /etc/fail2ban/filter.d/custom-sshd.conf

Result: Lines: 1 lines, 0 ignored, 1 matched, 0 missed [processed in 0.00 sec]

For full /var/log/auth.log file:

fail2ban-regex /var/log/auth.log /etc/fail2ban/filter.d/custom-sshd.conf

Result: Lines: 198 lines, 0 ignored, 14 matched, 184 missed [processed in 0.01 sec]

My jail.local:

[INCLUDES]

before = paths-debian.conf


[DEFAULT]

ignoreip = 127.0.0.1/8
bantime = 86400
findtime = 600
maxretry = 2
backend = auto
usedns = warn
logencoding = auto
filter = %(__name__)s
protocol = tcp
chain = INPUT
port = 0:65535
banaction = iptables-multiport
action_ = %(banaction)s[name=%(__name__)s, bantime="%(bantime)s", port="%(port)s", protocol="%(protocol)s", chain="%(chain)s"]
action = %(action_)s
enabled = false


[sshd]

enabled = true
port = ssh
filter = custom-sshd
logpath = %(sshd_log)s


[sshd-ddos]

enabled = true
port = ssh
logpath = %(sshd_log)s

My custom ssh filter /etc/fail2ban/filter.d/custom-sshd.conf file:

[INCLUDES]

before = common.conf

[Definition]

_daemon = sshd

failregex = ^%(__prefix_line)s[iI](?:llegal|nvalid) user .* from <HOST>\s*$

ignoreregex =

Relevant parts of /var/log/fail2ban.log file:

2018-04-15 10:53:23,670 fail2ban.server         [8510]: INFO    Stopping all jails
2018-04-15 10:53:23,810 fail2ban.jail           [8510]: INFO    Jail 'sshd' stopped
2018-04-15 10:53:24,914 fail2ban.jail           [8510]: INFO    Jail 'sshd-ddos' stopped
2018-04-15 10:53:24,918 fail2ban.server         [8510]: INFO    Exiting Fail2ban
2018-04-15 10:53:25,256 fail2ban.server         [8598]: INFO    Changed logging target to /var/log/fail2ban.log for Fail2ban v0.9.3
2018-04-15 10:53:25,257 fail2ban.database       [8598]: INFO    Connected to fail2ban persistent database '/var/lib/fail2ban/fail2ban.sqlite3'
2018-04-15 10:53:25,260 fail2ban.jail           [8598]: INFO    Creating new jail 'sshd'
2018-04-15 10:53:25,273 fail2ban.jail           [8598]: INFO    Jail 'sshd' uses pyinotify
2018-04-15 10:53:25,283 fail2ban.filter         [8598]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-15 10:53:25,286 fail2ban.jail           [8598]: INFO    Initiated 'pyinotify' backend
2018-04-15 10:53:25,289 fail2ban.filter         [8598]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-15 10:53:25,289 fail2ban.filter         [8598]: INFO    Set findtime = 600
2018-04-15 10:53:25,292 fail2ban.filter         [8598]: INFO    Added logfile = /var/log/auth.log
2018-04-15 10:53:25,294 fail2ban.actions        [8598]: INFO    Set banTime = 86400
2018-04-15 10:53:25,295 fail2ban.filter         [8598]: INFO    Set maxRetry = 2
2018-04-15 10:53:25,300 fail2ban.jail           [8598]: INFO    Creating new jail 'sshd-ddos'
2018-04-15 10:53:25,300 fail2ban.jail           [8598]: INFO    Jail 'sshd-ddos' uses pyinotify
2018-04-15 10:53:25,301 fail2ban.filter         [8598]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-15 10:53:25,304 fail2ban.jail           [8598]: INFO    Initiated 'pyinotify' backend
2018-04-15 10:53:25,307 fail2ban.filter         [8598]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-15 10:53:25,307 fail2ban.filter         [8598]: INFO    Set findtime = 600
2018-04-15 10:53:25,309 fail2ban.filter         [8598]: INFO    Added logfile = /var/log/auth.log
2018-04-15 10:53:25,312 fail2ban.actions        [8598]: INFO    Set banTime = 86400
2018-04-15 10:53:25,312 fail2ban.filter         [8598]: INFO    Set maxRetry = 2
2018-04-15 10:53:25,314 fail2ban.server         [8598]: INFO    Jail sshd-ddos is not a JournalFilter instance
2018-04-15 10:53:25,319 fail2ban.jail           [8598]: INFO    Jail 'sshd' started
2018-04-15 10:53:25,325 fail2ban.jail           [8598]: INFO    Jail 'sshd-ddos' started

Relevant lines from monitored /var/log/auth.log:

Apr 15 10:55:39 fail2ban sshd[8636]: Invalid user random from 189.166.145.133
Apr 15 10:55:39 fail2ban sshd[8636]: input_userauth_request: invalid user random [preauth]
Apr 15 10:55:39 fail2ban sshd[8636]: Connection closed by 189.166.145.133 port 45178 [preauth]
Apr 15 10:55:57 fail2ban sshd[8638]: Invalid user random from 189.166.145.133
Apr 15 10:55:57 fail2ban sshd[8638]: input_userauth_request: invalid user random [preauth]
Apr 15 10:55:57 fail2ban sshd[8638]: Connection closed by 189.166.145.133 port 45180 [preauth]
Apr 15 10:57:25 fail2ban sshd[8642]: Invalid user random from 189.166.145.133
Apr 15 10:57:25 fail2ban sshd[8642]: input_userauth_request: invalid user random [preauth]
Apr 15 10:57:25 fail2ban sshd[8642]: Connection closed by 189.166.145.133 port 45186 [preauth]

[sebres]

Just to clarify I understand the issue correct: if you check your custom-sshd via fail2ban-regex it finds some failures, within fail2ban it does not?

Can you check you see this rule if you dump the config parameters:

fail2ban-client -d | grep "sshd"

Second question BTW - why you need this customization at all? Because if I try your auth.log-excerpt with 0.9th version, I get 3 failures as expected:

$ fail2ban-regex -v ../test-filters/sshd-gh-2113.txt /prj/f2b-0.9/config/filter.d/sshd.conf

Running tests
=============

Use   failregex filter file : sshd, basedir: /prj/f2b-0.9/config
Use         maxlines : 10
Use         log file : ../test-filters/sshd-gh-2113.txt
Use         encoding : UTF-8


Results
=======

Failregex: 3 total
|-  #) [# of hits] regular expression
...
|   5) [3] ...[iI](?:llegal|nvalid) user .*? from <HOST>...
|      189.166.145.133  Sun Apr 15 10:55:39 2018
|      189.166.145.133  Sun Apr 15 10:55:57 2018
|      189.166.145.133  Sun Apr 15 10:57:25 2018
...
Lines: 9 lines, 0 ignored, 3 matched, 6 missed
[processed in 0.01 sec]

[Madh93]

Just to clarify I understand the issue correct: if you check your custom-sshd via fail2ban-regex it finds some failures, within fail2ban it does not?

Exactly.

The fail2ban-client -d | grep "sshd" output:

['add', 'sshd', 'auto']
['set', 'sshd', 'addlogpath', '/var/log/auth.log', 'head']
['set', 'sshd', 'ignorecommand', '']
['set', 'sshd', 'maxretry', 2]
['set', 'sshd', 'bantime', 86400]
['set', 'sshd', 'findtime', 600]
['set', 'sshd', 'logencoding', 'auto']
['set', 'sshd', 'usedns', 'warn']
['set', 'sshd', 'addignoreip', '127.0.0.1/8']
['set', 'sshd', 'addfailregex', '^\\s*(<[^.]+\\.[^.]+>)?\\s*(?:\\S+ )?(?:kernel: \\[ *\\d+\\.\\d+\\] )?(?:@vserver_\\S+ )?(?:(?:\\[\\d+\\])?:\\s+[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?|[\\[\\(]?sshd(?:\\(\\S+\\))?[\\]\\)]?:?(?:\\[\\d+\\])?:?)?\\s(?:\\[ID \\d+ \\S+\\])?\\s*[iI](?:llegal|nvalid) user .* from <HOST>\\s*$']
['set', 'sshd', 'addaction', 'iptables-multiport']
['set', 'sshd', 'action', 'iptables-multiport', 'actioncheck', "<iptables> -n -L <chain> | grep -q 'f2b-<name>[ \\t]'"]
['set', 'sshd', 'action', 'iptables-multiport', 'actionstart', '<iptables> -N f2b-<name>\n<iptables> -A f2b-<name> -j <returntype>\n<iptables> -I <chain> -p <protocol> -m multiport --dports <port> -j f2b-<name>']
['set', 'sshd', 'action', 'iptables-multiport', 'actionstop', '<iptables> -D <chain> -p <protocol> -m multiport --dports <port> -j f2b-<name>\n<iptables> -F f2b-<name>\n<iptables> -X f2b-<name>']
['set', 'sshd', 'action', 'iptables-multiport', 'actionunban', '<iptables> -D f2b-<name> -s <ip> -j <blocktype>']
['set', 'sshd', 'action', 'iptables-multiport', 'actionban', '<iptables> -I f2b-<name> 1 -s <ip> -j <blocktype>']
['set', 'sshd', 'action', 'iptables-multiport', 'protocol', 'tcp']
['set', 'sshd', 'action', 'iptables-multiport', 'port', 'ssh']
['set', 'sshd', 'action', 'iptables-multiport', 'blocktype', 'REJECT --reject-with icmp-port-unreachable']
['set', 'sshd', 'action', 'iptables-multiport', 'known/chain', 'INPUT']
['set', 'sshd', 'action', 'iptables-multiport', 'chain', 'INPUT']
['set', 'sshd', 'action', 'iptables-multiport', 'name', 'sshd']
['set', 'sshd', 'action', 'iptables-multiport', 'known/returntype', 'RETURN']
['set', 'sshd', 'action', 'iptables-multiport', 'known/protocol', 'tcp']
['set', 'sshd', 'action', 'iptables-multiport', 'lockingopt', '-w']
['set', 'sshd', 'action', 'iptables-multiport', 'known/blocktype', 'REJECT --reject-with icmp-port-unreachable']
['set', 'sshd', 'action', 'iptables-multiport', 'known/port', 'ssh']
['set', 'sshd', 'action', 'iptables-multiport', 'bantime', '86400']
['set', 'sshd', 'action', 'iptables-multiport', 'iptables', 'iptables <lockingopt>']
['set', 'sshd', 'action', 'iptables-multiport', 'returntype', 'RETURN']
['set', 'sshd', 'action', 'iptables-multiport', 'known/lockingopt', '-w']
['set', 'sshd', 'action', 'iptables-multiport', 'known/iptables', 'iptables <lockingopt>']
['set', 'sshd', 'action', 'iptables-multiport', 'known/name', 'default']
['start', 'sshd']

Second question BTW - why you need this customization at all? Because if I try your auth.log-excerpt with 0.9th version, I get 3 failures as expected.

You're right, it isn't neccessary to add a custom filter when sshd.conf already has the regex I want. I didn't see before. I've edited my jail to get default sshd.conf filter:

....
[sshd]
enabled = true
port = ssh
logpath = %(sshd_log)s
....

After restart fail2ban I have the same problem: fail2ban-regex finds some failures, but fail2ban doesn't.

[sebres]

The config-dump looks fine, and I don't see something wrong there.
Possibly the backend (pyinotify selected by auto) has some problems on your system.
Just to be sure, please try to change the backend to polling (and restart):

[sshd]
backend = polling
...

If nothing will change, you should try to start fail2ban with DEBUG logging, possibly then one can see more.

[Madh93]

Okey, I've changed the backend to polling with no results, so I've started DEBUG logging:

sudo fail2ban-client set log-level DEBUG

And the /var/log/fail2ban.log file content is:

2018-04-17 22:30:04,836 fail2ban.transmitter    [13479]: DEBUG   Command: ['stop']
2018-04-17 22:30:04,837 fail2ban.asyncserver    [13479]: DEBUG   Removed socket file /var/run/fail2ban/fail2ban.sock
2018-04-17 22:30:04,837 fail2ban.asyncserver    [13479]: DEBUG   Socket shutdown
2018-04-17 22:30:04,837 fail2ban.server         [13479]: INFO    Stopping all jails
2018-04-17 22:30:04,837 fail2ban.server         [13479]: DEBUG   Stopping jail sshd
2018-04-17 22:30:04,918 fail2ban.actions        [13479]: DEBUG   Flush ban list
2018-04-17 22:30:04,920 fail2ban.action         [13479]: DEBUG   iptables -w -D INPUT -p tcp -m multiport --dports ssh -j f2b-sshd
iptables -w -F f2b-sshd
iptables -w -X f2b-sshd
2018-04-17 22:30:05,023 fail2ban.action         [13479]: DEBUG   iptables -w -D INPUT -p tcp -m multiport --dports ssh -j f2b-sshd
iptables -w -F f2b-sshd
iptables -w -X f2b-sshd -- stdout: b''
2018-04-17 22:30:05,023 fail2ban.action         [13479]: DEBUG   iptables -w -D INPUT -p tcp -m multiport --dports ssh -j f2b-sshd
iptables -w -F f2b-sshd
iptables -w -X f2b-sshd -- stderr: b''
2018-04-17 22:30:05,023 fail2ban.action         [13479]: DEBUG   iptables -w -D INPUT -p tcp -m multiport --dports ssh -j f2b-sshd
iptables -w -F f2b-sshd
iptables -w -X f2b-sshd -- returned successfully
2018-04-17 22:30:05,024 fail2ban.actions        [13479]: DEBUG   sshd: action terminated
2018-04-17 22:30:05,085 fail2ban.filterpoll     [13479]: DEBUG   sshd filter terminated
2018-04-17 22:30:05,085 fail2ban.jail           [13479]: INFO    Jail 'sshd' stopped
2018-04-17 22:30:05,090 fail2ban.server         [13479]: DEBUG   Remove PID file /var/run/fail2ban/fail2ban.pid
2018-04-17 22:30:05,095 fail2ban.server         [13479]: INFO    Exiting Fail2ban
2018-04-17 22:30:05,517 fail2ban.server         [13581]: INFO    Changed logging target to /var/log/fail2ban.log for Fail2ban v0.9.3
2018-04-17 22:30:05,517 fail2ban.database       [13581]: INFO    Connected to fail2ban persistent database '/var/lib/fail2ban/fail2ban.sqlite3'
2018-04-17 22:30:05,521 fail2ban.jail           [13581]: INFO    Creating new jail 'sshd'
2018-04-17 22:30:05,522 fail2ban.jail           [13581]: INFO    Jail 'sshd' uses poller
2018-04-17 22:30:05,539 fail2ban.filter         [13581]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-17 22:30:05,539 fail2ban.jail           [13581]: INFO    Initiated 'polling' backend
2018-04-17 22:30:05,543 fail2ban.filter         [13581]: INFO    Set maxRetry = 2
2018-04-17 22:30:05,544 fail2ban.filter         [13581]: INFO    Set jail log file encoding to ANSI_X3.4-1968
2018-04-17 22:30:05,545 fail2ban.actions        [13581]: INFO    Set banTime = 86400
2018-04-17 22:30:05,549 fail2ban.filter         [13581]: INFO    Added logfile = /var/log/auth.log
2018-04-17 22:30:05,551 fail2ban.filter         [13581]: INFO    Set findtime = 600
2018-04-17 22:30:05,552 fail2ban.filter         [13581]: INFO    Set maxlines = 10
2018-04-17 22:30:05,698 fail2ban.server         [13581]: INFO    Jail sshd is not a JournalFilter instance
2018-04-17 22:30:05,715 fail2ban.jail           [13581]: INFO    Jail 'sshd' started
2018-04-17 22:30:14,907 fail2ban.filterpoll     [13581]: DEBUG   /var/log/auth.log has been modified
2018-04-17 22:30:14,908 fail2ban.datedetector   [13581]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,908 fail2ban.datedetector   [13581]: DEBUG   Got time 1523997014.000000 for "'Apr 17 21:30:14'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,910 fail2ban.datedetector   [13581]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,910 fail2ban.datedetector   [13581]: DEBUG   Got time 1523997014.000000 for "'Apr 17 21:30:14'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,912 fail2ban.datedetector   [13581]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,912 fail2ban.datedetector   [13581]: DEBUG   Got time 1523997014.000000 for "'Apr 17 21:30:14'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:30:14,915 fail2ban.datedetector   [13581]: DEBUG   Sorting the template list
2018-04-17 22:30:14,915 fail2ban.datedetector   [13581]: DEBUG   Winning template: (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)? with 2947 hits

When a ssh connection fails:

2018-04-17 22:52:42,832 fail2ban.filterpoll     [14000]: DEBUG   /var/log/auth.log has been modified
2018-04-17 22:52:42,832 fail2ban.datedetector   [14000]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,833 fail2ban.datedetector   [14000]: DEBUG   Got time 1523998362.000000 for "'Apr 17 21:52:42'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,833 fail2ban.filter         [14000]: DEBUG   Processing line with time:1523998362.0 and ip:189.166.145.133
2018-04-17 22:52:42,833 fail2ban.filter         [14000]: DEBUG   Ignore line since time 1523998362.0 < 1524001962.8336427 - 600
2018-04-17 22:52:42,833 fail2ban.datedetector   [14000]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,834 fail2ban.datedetector   [14000]: DEBUG   Got time 1523998362.000000 for "'Apr 17 21:52:42'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,835 fail2ban.datedetector   [14000]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,836 fail2ban.datedetector   [14000]: DEBUG   Got time 1523998362.000000 for "'Apr 17 21:52:42'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:52:42,841 fail2ban.datedetector   [14000]: DEBUG   Sorting the template list
2018-04-17 22:52:42,841 fail2ban.datedetector   [14000]: DEBUG   Winning template: (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)? with 3179 hits

I don't know what is happening. I tried to change encoding variable with no success. Maybe in this line is there a hint?

Ignore line since time 1523998362.0 < 1524001962.8336427 - 600

Where 600 seems to be findtime = 600 in jail.local.

Here the log when after 3 retries ssh connections:

2018-04-17 22:59:41,312 fail2ban.filterpoll     [14042]: DEBUG   /var/log/auth.log has been modified
2018-04-17 22:59:41,312 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,313 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998780.000000 for "'Apr 17 21:59:40'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,313 fail2ban.filter         [14042]: DEBUG   Processing line with time:1523998780.0 and ip:189.166.145.133
2018-04-17 22:59:41,313 fail2ban.filter         [14042]: DEBUG   Ignore line since time 1523998780.0 < 1524002381.3136334 - 600
2018-04-17 22:59:41,313 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,314 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998780.000000 for "'Apr 17 21:59:40'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,315 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,315 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998780.000000 for "'Apr 17 21:59:40'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:41,319 fail2ban.datedetector   [14042]: DEBUG   Sorting the template list
2018-04-17 22:59:41,320 fail2ban.datedetector   [14042]: DEBUG   Winning template: (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)? with 3203 hits
2018-04-17 22:59:44,323 fail2ban.filterpoll     [14042]: DEBUG   /var/log/auth.log has been modified
2018-04-17 22:59:44,324 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,325 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998783.000000 for "'Apr 17 21:59:43'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,325 fail2ban.filter         [14042]: DEBUG   Processing line with time:1523998783.0 and ip:189.166.145.133
2018-04-17 22:59:44,325 fail2ban.filter         [14042]: DEBUG   Ignore line since time 1523998783.0 < 1524002384.3257287 - 600
2018-04-17 22:59:44,326 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,326 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998783.000000 for "'Apr 17 21:59:43'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,328 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,328 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998783.000000 for "'Apr 17 21:59:43'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:44,332 fail2ban.datedetector   [14042]: DEBUG   Sorting the template list
2018-04-17 22:59:44,333 fail2ban.datedetector   [14042]: DEBUG   Winning template: (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)? with 3206 hits
2018-04-17 22:59:46,335 fail2ban.filterpoll     [14042]: DEBUG   /var/log/auth.log has been modified
2018-04-17 22:59:46,336 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,336 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998786.000000 for "'Apr 17 21:59:46'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,337 fail2ban.filter         [14042]: DEBUG   Processing line with time:1523998786.0 and ip:189.166.145.133
2018-04-17 22:59:46,337 fail2ban.filter         [14042]: DEBUG   Ignore line since time 1523998786.0 < 1524002386.337238 - 600
2018-04-17 22:59:46,337 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,337 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998786.000000 for "'Apr 17 21:59:46'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,339 fail2ban.datedetector   [14042]: DEBUG   Matched time template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,339 fail2ban.datedetector   [14042]: DEBUG   Got time 1523998786.000000 for "'Apr 17 21:59:46'" using template (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)?
2018-04-17 22:59:46,343 fail2ban.datedetector   [14042]: DEBUG   Sorting the template list
2018-04-17 22:59:46,343 fail2ban.datedetector   [14042]: DEBUG   Winning template: (?:DAY )?MON Day 24hour:Minute:Second(?:\.Microseconds)?(?: Year)? with 3209 hits

[sebres]

Looks like timezone issue (see #1959 and similar).
With other words f2b seems to run in another TZ as the sshd, rsyslog etc.

[Madh93]

That's it! I don't know what service has the different TZ (I have to investigate it...), but after rising findtime value fail2ban works perfectly.

Thank you very much :smile:

UPDATE

Yes, it was rsyslog whose TZ was incorrect. It only was necessary to restart it:

systemctl restart rsyslog