Dovecot reposting inactivity as auth failed
Hi , i am having an issue with dovecot , in log files of imap inactivity lines have the word included "auth failed" , witch is not true , what happens next is that fail2ban is looking for that word too in log file of dovecot ,and when it finds it it bans my public ip address . Is there any change to change this behavior in dovecot , what i mean is to insert "auth failed" when in fact it is an authentication failed , and not use it as general for every thing in log file .
Dovecot Version : 2.3.19.1 (9b53102964)
Log imap line with issues : dovecot: imap-login: Disconnected: Inactivity (auth failed, 1 attempts in 180 secs): user=<myemail@mydomain>, method=PLAIN, rip=xxx.xxx.xx.xx, lip=xxx.xxx.xxx.xxx, TLS, TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits), session=<some_hash>
Thank you
On 6/16/23 10:53, pedro@netsecpt.pt wrote:
Hi , i am having an issue with dovecot , in log files of imap inactivity lines have the word included "auth failed" , witch is not true , what happens next is that fail2ban is looking for that word too in log file of dovecot ,and when it finds it it bans my public ip address . Is there any change to change this behavior in dovecot , what i mean is to insert "auth failed" when in fact it is an authentication failed , and not use it as general for every thing in log file .
Interesting. It does look like maybe dovecot is reporting "auth failed" on inactivity even if the auth actually succeeded. I am on Dovecot 2.3.20 from the dovecot APT repo for Ubuntu.
I don't see this for my mail account, because my mail clients are never inactive for 3 minutes. But I do see it for another account on my mail server. I will need to ask that user if it is possible they are actually sending an incorrect password, but I think that is unlikely. The log entries are not frequent and it looks like there are only ever two such failures close enough together for fail2ban to notice, so the source address is not being banned because my fail2ban config requires five failures within 20 minutes before it takes action.
What is the findtime and maxretry in your fail2ban jail config for dovecot? Maybe the time span is too large or the retry value too low.
I think you should have fail2ban ignore your public IP which would solve the problem for your IP address. Below is the contents of /etc/fail2ban/jail.d/zz-custom.conf on my mail server. I have not changed any of the conf files in /etc/fail2ban itself, I have only added a config file to jail.d.
The public /24 ranges in the ignoreip setting are in there for qualys labs SSL tests. Without them, their test IP address gets banned because their tests generate a ton of failures in the haproxy log. Also included is the AWS private IP address of the mail server, and the AWS public IP address.
elyograg@bilbo:/etc/fail2ban/jail.d$ cat zz-custom.conf [INCLUDES] before = common.conf
[DEFAULT] maxretry = 5 bantime = 8h findtime = 20m ignoreself = true ignoreip = 127.0.0.1/8 ::1 192.168.217.0/24 REDACTED1 172.31.8.104 REDACTED2 REDACTED3 64.41.200.0/24 54.67.1.252 64.77.246.0/24 banaction = %(banaction_allports)s protocol = all
[sshd] enabled = true port = 0:65535
[dovecot] enabled = true port = 0:65535
[sieve] enabled = true port = 0:65535
[postfix] enabled = true findtime = 30m bantime = 8h port = 0:65535
[postfix-rbl] enabled = true findtime = 30m bantime = 8h port = 0:65535
[postfix-sasl] enabled = true findtime = 30m bantime = 8h port = 0:65535
[haproxy-http-auth] enabled = true logpath = /var/log/debug-haproxy port = 0:65535
[haproxy-custom] enabled = true findtime = 30m logpath = /var/log/debug-haproxy maxretry = 10 port = 0:65535
I am not using custom rules for fail2ban , in fact my fail2ban is using the default settings , i do not have that file zzz-custom in that directory however jail.conf is using the default jail time for every filter , witch is :
# "bantime" is the number of seconds that a host is banned. bantime = 10m
# A host is banned if it has generated "maxretry" during the last "findtime" # seconds. findtime = 10m
# "maxretry" is the number of failures before a host get banned. maxretry = 5
# "maxmatches" is the number of matches stored in ticket (resolvable via tag <matches> in actions). maxmatches = %(maxretry)s
The issue i was having was due 2 mail clients with bad configuration i had on my iphone , iphone already comes with a mail client that i configured in the past , however recently i was unable to find its icon and i installed outlook too , but then 1 week ago i had to reinstall the mail server again due to a hdd failure , since iphone was conected to my lan using wifi then i got in mail server my public ip , this was the reason why auth failure was in log file , inactivity was probably because those clients hang too long in imap and dovecot reported 1st the failed authentication and then after that reported the same failed auth but with inactivity witch is related so same client . After removing the configurations from both clients in iphone this did not happened again .
On 6/19/2023 2:21 PM, pedro@netsecpt.pt wrote:
I am not using custom rules for fail2ban , in fact my fail2ban is using the default settings , i do not have that file zzz-custom in that directory however jail.conf is using the default jail time for every filter , witch is :
I created the zz-custom.conf file myself. You won't find it in a standard fail2ban install. It is my way of achieving the config I want without changing the main .conf files. This makes upgrades a lot cleaner.
I believe dovecot does have a bug here. My user that shows those failed auth messages has not been using the wrong password. My guess is that anytime dovecot disconnects a user for inactivity, it claims that auth failed, even when that is not the case.
Interesting. In the 2.3.20 tag, I found the code that prints that message in src/login-common/client-common.c ... but that same code is not present in the main branch. It looks to me like that code has been completely overhauled and maybe 2.4 won't have this problem when it gets released.
It's been decades since I last did any C development, so I'm not really good at tracking what's going on in the code, but I see that the client_get_extra_disconnect_reason function in that source file uses that "auth failed" message as its fall-through option, and there doesn't seem to be any test earlier in the function to detect when the disconnect happens because of inactivity on a successfully authenticated connection.
Fixing the problem is beyond my current skill level. It will require somebody who is intimately familiar with that code.
Thanks, Shawn
On 6/19/2023 10:52 PM, Shawn Heisey wrote:
Interesting. In the 2.3.20 tag, I found the code that prints that message in src/login-common/client-common.c ... but that same code is not present in the main branch. It looks to me like that code has been completely overhauled and maybe 2.4 won't have this problem when it gets released.
Hmm. Maybe I am wrong. I grepped my log for inactivity disconnects that do not say "auth failed". All of the things it found were for my email address, and had a timeout of 1800 seconds, not 180 seconds like the ones for the other user that say "auth failed."
elyograg@bilbo:~$ sudo grep Inactivity /var/log/mail.log | grep -v "auth failed" Jun 18 04:20:18 bilbo dovecot: imap(elyograg@elyograg.org)<412591><RU31J1H+3Ipiyj9k>: Disconnected: Inactivity - no input for 1800 secs in=38963 out=457431 deleted=0 expunged=0 trashed=0 hdr_count=1 hdr_bytes=230 body_count=1 body_bytes=10647 Jun 18 04:24:28 bilbo dovecot: imap(elyograg@elyograg.org)<340404><MAs7kUj+MIRiyj9k>: Disconnected: Inactivity - no input for 1800 secs in=69198 out=823917 deleted=0 expunged=0 trashed=0 hdr_count=3 hdr_bytes=2163 body_count=3 body_bytes=47071 Jun 18 22:42:04 bilbo dovecot: imap(elyograg@elyograg.org)<701301><ocx5eXP+1Jxiyj9k>: Disconnected: Inactivity - no input for 1801 secs in=4726 out=13697 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jun 19 03:18:37 bilbo dovecot: imap(elyograg@elyograg.org)<579102><BBDeymT+npBiyj9k>: Disconnected: Inactivity - no input for 1800 secs in=8330 out=102365 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jun 19 08:58:05 bilbo dovecot: imap(elyograg@elyograg.org)<773980><k1Y29nv+bJhiyj9k>: Disconnected: Inactivity - no input for 1800 secs in=4710 out=13725 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jun 19 18:05:50 bilbo dovecot: imap(elyograg@elyograg.org)<841537><caqd/oP+5o9iyj9k>: Disconnected: Inactivity - no input for 1800 secs in=174 out=4799 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Jun 19 19:29:21 bilbo dovecot: imap(elyograg@elyograg.org)<577941><W+dvpWT+qKxiyj9k>: Disconnected: Inactivity - no input for 1801 secs in=28256 out=331141 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0
So maybe the other user with the auth failed messages was actually failing auth. Today they actually got banned by fail2ban because they had a ton of the "auth failed" logs in quick succession. I re-iterated the correct IMAP server settings and there hasn't been a repeat of that log message since that time. Maybe they had actually typed in the password wrong.
Apologies for the noise!
Thanks, Shawn
On 20/06/2023 07:17, Shawn Heisey wrote:
Hmm. Maybe I am wrong. I grepped my log for inactivity disconnects that do not say "auth failed". All of the things it found were for my email address, and had a timeout of 1800 seconds, not 180 seconds like the ones for the other user that say "auth failed."
https://wiki.dovecot.org/Timeouts
180 seconds is the "CLIENT_LOGIN_TIMEOUT_MSECS", which means the user has *not* been authenticated yet.
I can reproduce the message you're seeing through a simple IMAP session like this:
~ % telnet <mailserver> 143 Trying <ip>... Connected to <mailserver>. Escape character is '^]'.
- OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ STARTTLS AUTH=PLAIN] <mailserver> ready. a1 login foo bar a1 NO [AUTHENTICATIONFAILED] Authentication failed.
[3 minutes later]
- BYE Disconnected for inactivity.
This produces the following log output:
imap-login: Info: Disconnected: Inactivity (auth failed, 1 attempts in 174 secs): user=<foo>, orig=<foo>, method=PLAIN, proto=imap, rip=[rip], lip=[lip], session=[session_id]
It seems likely that the logs you're seeing are actually sessions with no successful login. If that weren't the case, you should be able to find a log line for the successful login if you search your logs for the IMAP session ID, e.g. something like:
imap-login: Info: Login: user=<foo>, orig=<foo>, method=PLAIN, proto=imap, rip=[rip], lip=[lip], session=[session_id], secured
Best regards, Eirik
Yes that was what i tough , since i removed those client apps from my phone i did not had any more issues with my public ip being banned or any line in log with the word "auth fail" where i log in . It looks like most error logs i get here are : (Someone trying to force SSL on TLS 1.3 connection , probably to exploit some vulnerability in SSL1,2 and 3 in case of success ) dovecot: imap-login: Disconnected: Connection closed: SSL_accept() failed: error:0A00010B:SSL routines::wrong version number (disconnected before auth was ready, waited 0 secs): user=<>, rip=xxx.xxx. xxx.xxx, lip=XXX.XXX.XXX.XXX, TLS handshaking: SSL_accept() failed:error:0A00010B:SSL routines::wrong version number, session=<some_hash>
or this one witch looks like manual input over telnet to try something
dovecot: imap-login: Disconnected: Too many invalid commands (no auth attempts in 0 secs): user=<>, rip=xxx.xxx.xxx.xxx, lip=xxx.xxx.xxx.xxx, session=<some_hash>
Honestly none of these ips have good intentions or are from valid domains , i will probably create a bash script that i will run daily to catch all of these attempts and ban the ip forever in iptables , more easier to solve this issue than giving that person 10 minutes or hours of ban time and then retry again .
participants (3)
-
Eirik Rye
-
pedro＠netsecpt.pt
-
Shawn Heisey