Valid SSH logins end in a ban

[j-schulz]

The following regex matches valid logins

^<F-MLFFORGET><F-MLFGAINED>Accepted \w+</F-MLFGAINED></F-MLFFORGET> for <F-USER>\S+</F-USER> from <HOST>(?:\s|$)

You can reproduce it with:

ssh n.n.n.n date

Log:

Aug 8 12:10:41 test1 sshd[5657]: Accepted publickey for root from n.n.n.n port 54872 ssh2: RSA SHA256:...
Aug 8 12:10:41 test1 sshd[5657]: Received disconnect from n.n.n.n port 54872:11: disconnected by user
Aug 8 12:10:41 test1 sshd[5657]: Disconnected from user root n.n.n.n port 54872

Valid logins shouldn't end in a ban.

Edit: using sshd.conf from latest commit

[j-schulz]

Jail:

[sshd]
enabled = true
filter = sshd
action = %(action_)s
logpath = /var/log/auth.log
mode = normal
maxretry = 3

Execute 3 times ssh n.n.n.n date

From fail2ban.log:

2020-08-08 13:11:55,162 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:11:55,162 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:11:55,169 fail2ban.filter [6534]: DEBUG Processing line with time:1596885114.0 and ip:N.N.N.N
2020-08-08 13:11:55,181 fail2ban.filter [6534]: INFO [sshd] Found N.N.N.N - 2020-08-08 13:11:54
2020-08-08 13:11:55,181 fail2ban.failmanager [6534]: DEBUG Total # of detected failures: 1. Current failures from 1 IPs (IP:count): N.N.N.N:1
2020-08-08 13:11:59,990 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:11:59,990 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:11:59,991 fail2ban.filter [6534]: DEBUG Processing line with time:1596885119.0 and ip:N.N.N.N
2020-08-08 13:11:59,991 fail2ban.filter [6534]: INFO [sshd] Found N.N.N.N - 2020-08-08 13:11:59
2020-08-08 13:11:59,991 fail2ban.failmanager [6534]: DEBUG Total # of detected failures: 2. Current failures from 1 IPs (IP:count): N.N.N.N:2
2020-08-08 13:12:00,891 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,891 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:00,891 fail2ban.filter [6534]: DEBUG Processing line with time:1596885120.0 and ip:N.N.N.N
2020-08-08 13:12:00,892 fail2ban.filter [6534]: INFO [sshd] Found N.N.N.N - 2020-08-08 13:12:00
2020-08-08 13:12:00,892 fail2ban.failmanager [6534]: DEBUG Total # of detected failures: 3. Current failures from 1 IPs (IP:count): N.N.N.N:3
2020-08-08 13:12:00,895 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,896 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:00,903 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,903 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:00,967 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,967 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:00,974 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,976 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:00,976 fail2ban.filterpyinotify[6534]: DEBUG Event queue size: 16
2020-08-08 13:12:00,977 fail2ban.filterpyinotify[6534]: DEBUG <_RawEvent cookie=0 mask=0x2 name='' wd=2 >
2020-08-08 13:12:01,666 fail2ban.actions [6534]: NOTICE [sshd] Ban N.N.N.N
2020-08-08 13:12:01,666 fail2ban.action [6534]: DEBUG iptables -w -N f2b-sshd
iptables -w -A f2b-sshd -j RETURN
iptables -w -I INPUT -p tcp -j f2b-sshd
2020-08-08 13:12:01,682 fail2ban.utils [6534]: DEBUG 7fd997194c10 -- returned successfully 0
2020-08-08 13:12:01,683 fail2ban.action [6534]: DEBUG iptables -w -n -L INPUT | grep -q 'f2b-sshd[ \t]'
2020-08-08 13:12:01,691 fail2ban.utils [6534]: DEBUG 7fd996fe2648 -- returned successfully 0
2020-08-08 13:12:01,692 fail2ban.action [6534]: DEBUG iptables -w -I f2b-sshd 1 -s N.N.N.N -j REJECT --reject-with icmp-port-unreachable
2020-08-08 13:12:01,698 fail2ban.utils [6534]: DEBUG 7fd996fc8390 -- returned successfully 0
2020-08-08 13:12:01,698 fail2ban.actions [6534]: DEBUG Banned 1 / 1, 1 ticket(s) in 'sshd'

From auth.log:

Aug 8 13:11:54 test1 sshd[6540]: Accepted publickey for root from N.N.N.N port 55342 ssh2: RSA SHA256:...
Aug 8 13:11:55 test1 sshd[6540]: Received disconnect from N.N.N.N port 55342:11: disconnected by user
Aug 8 13:11:55 test1 sshd[6540]: Disconnected from user root N.N.N.N port 55342
Aug 8 13:11:59 test1 sshd[6548]: Accepted publickey for root from N.N.N.N port 55346 ssh2: RSA SHA256:...
Aug 8 13:11:59 test1 sshd[6548]: Received disconnect from N.N.N.N port 55346:11: disconnected by user
Aug 8 13:11:59 test1 sshd[6548]: Disconnected from user root N.N.N.N port 55346
Aug 8 13:12:00 test1 sshd[6556]: Accepted publickey for root from N.N.N.N port 55348 ssh2: RSA SHA256:...
Aug 8 13:12:00 test1 sshd[6556]: Received disconnect from N.N.N.N port 55348:11: disconnected by user
Aug 8 13:12:00 test1 sshd[6556]: Disconnected from user root N.N.N.N port 55348

[sebres]

The following regex matches valid logins

Yes, although it's matching this RE (due to helper tag <F-MLFGAINED>) signals a gained successful connection, so every previous failures of sshd[5657] get forgotten (see #2279).

Also see #2632 for similar issue.

Anyway if I try fail2ban-regex with your excerpt, I see no failure generated:

$ fail2ban-regex -o row /tmp/gh-2799.txt sshd

$ fail2ban-regex /tmp/gh-2799.txt sshd

...
Results
=======

Failregex: 2 total
|-  #) [# of hits] regular expression
|  19) [1] ^<F-NOFAIL>Received <F-MLFFORGET>disconnect</F-MLFFORGET></F-NOFAIL> from <HOST>(?: (?:port \d+|on \S+)){0,2}:\s*11:
|  21) [1] ^<F-MLFFORGET><F-MLFGAINED>Accepted \w+</F-MLFGAINED></F-MLFFORGET> for <F-USER>\S+</F-USER> from <HOST>(?:\s|$)
`-

...
Lines: 3 lines, 2 ignored, 0 matched, 1 missed
[processed in 0.00 sec]

|- Ignored line(s):
|  Aug 8 12:10:41 test1 sshd[5657]: Accepted publickey for root from 192.0.2.1 port 54872 ssh2: RSA SHA256:...
|  Aug 8 12:10:41 test1 sshd[5657]: Received disconnect from 192.0.2.1 port 54872:11: disconnected by user
`-
|- Missed line(s):
|  Aug 8 12:10:41 test1 sshd[5657]: Disconnected from user root 192.0.2.1 port 54872
`-