Dovecot not responding

A user reported that she wasn't receiving any email. When I logged into the mail servers, which runs Dovecot for POP3/POP3S and used Telnet to connect to port 110, the well-known port for POP3, I didn't get any response after I entered the user command, so I exited to the telnet prompt with Ctrl-].

$ telnet 127.0.0.1 110
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
user nell
^]
telnet> quit
Connection closed.
$

I logged into the root account and checked today's and yesterday's maillog files for any references to Dovecot or POP3 issues, but saw none.

Udemy - April2516-25off-sitewide120x600
# grep -i dovecot /var/log/maillog
# grep -i dovecot /var/log/maillog.1
# grep -i pop3 /var/log/maillog.1
# grep -i pop3 /var/log/maillog
#

When I checked on the Dovecot processes that were running, I found far more than expected.

# ps -aux | grep dovecot
dovenull   613  0.0  0.1  45164  3260 ?        S    05:34   0:00 dovecotpop3-login
dovenull   876  0.0  0.1  45164  3260 ?        S    05:39   0:00 dovecotpop3-login
dovenull   889  0.0  0.1  45164  3260 ?        S    05:40   0:00 dovecotpop3-login
dovenull  1032  0.0  0.1  45164  3260 ?        S    05:44   0:00 dovecotpop3-login
root      1431  0.0  0.0  19868  1388 ?        Ss   Feb17   0:01 /usr/sbin/dovecot/g -F
root      1643  0.0  0.0  12524  1304 ?        S    Feb20   0:00 dovecotpop3
dovenull  3245  0.0  0.1  45164  3264 ?        S    06:14   0:00 dovecotpop3-login
dovecot/g   3314  0.0  0.0   9444   896 ?        S    Feb17   0:00 dovecot/anvil
dovenull  3593  0.0  0.1  45164  3260 ?        S    06:24   0:00 dovecotpop3-login
root      3995  0.0  0.0  12524  1308 ?        S    Feb20   0:00 dovecotpop3
dovenull  5242  0.0  0.1  45164  3264 ?        S    06:39   0:00 dovecotpop3-login
dovenull  5527  0.0  0.1  45164  3264 ?        S    06:44   0:00 dovecotpop3-login
dovenull  6258  0.0  0.1  45164  3264 ?        S    06:55   0:00 dovecotpop3-login
root      6519  0.0  0.0  12524  1304 ?        S    Feb20   0:00 dovecotpop3
dovenull  7026  0.0  0.1  45164  3264 ?        S    07:04   0:00 dovecotpop3-login
dovenull  7294  0.0  0.1  45164  3264 ?        S    07:09   0:00 dovecotpop3-login
dovenull  7510  0.0  0.1  45164  3260 ?        S    07:14   0:00 dovecotpop3-login
<text snipped>

When I counted them, I found there were 99 such processes.

# ps -aux | grep dovecot | grep -v grep | wc -l
99
#

And 71 of those referenced pop3-login.

# ps -aux | grep pop3-login | grep -v grep | wc -l
71
#

I also found 37 timeout references in today's maillog file.

# grep timeout /var/log/maillog
Feb 21 00:38:41 moonpoint sendmail[12275]: v1L5aatF012273: timeout waiting for input from local during Draining Input
Feb 21 00:48:10 moonpoint sendmail[12750]: v1L5k9nl012746: timeout waiting for input from local during Draining Input
Feb 21 01:30:41 moonpoint sendmail[16960]: v1L6SdwD016959: timeout waiting for input from local during Draining Input
Feb 21 05:50:37 moonpoint sendmail[1110]: v1LAmBiK001084: timeout waiting for input from local during Draining Input
Feb 21 05:50:48 moonpoint sendmail[1114]: v1LAmBiM001084: timeout waiting for input from local during Draining Input
Feb 21 05:50:49 moonpoint sendmail[1116]: v1LAmBiN001084: timeout waiting for input from local during Draining Input
Feb 21 05:51:10 moonpoint sendmail[1124]: v1LAmBiO001084: timeout waiting for input from local during Draining Input
Feb 21 06:07:58 moonpoint sendmail[3025]: v1LB5u4S003024: timeout waiting for input from local during Draining Input
Feb 21 06:10:27 moonpoint sendmail[31526]: v1LAAMc3031526: timeout waiting for input from [117.243.177.152] during server cmd read
Feb 21 06:24:26 moonpoint sendmail[3560]: v1LBMPth003557: timeout waiting for input from local during Draining Input
Feb 21 06:24:26 moonpoint sendmail[3559]: v1LBMPmr003558: timeout waiting for input from local during Draining Input
Feb 21 06:24:27 moonpoint sendmail[3563]: v1LBMPmt003558: timeout waiting for input from local during Draining Input
Feb 21 06:24:27 moonpoint sendmail[3564]: v1LBMPtj003557: timeout waiting for input from local during Draining Input
Feb 21 06:32:07 moonpoint sendmail[4874]: v1LBU6Lk004872: timeout waiting for input from local during Draining Input
Feb 21 07:42:53 moonpoint sendmail[9264]: v1LCe4vO009224: timeout waiting for input from local during Draining Input
Feb 21 07:44:23 moonpoint sendmail[9340]: v1LCgKx5009337: timeout waiting for input from local during Draining Input
Feb 21 07:46:20 moonpoint sendmail[9382]: v1LCiBdE009366: timeout waiting for input from local during Draining Input
Feb 21 07:52:02 moonpoint sendmail[9512]: v1LCo00Y009500: timeout waiting for input from local during Draining Input
Feb 21 07:52:02 moonpoint sendmail[9518]: v1LCo00Z009500: timeout waiting for input from local during Draining Input
Feb 21 07:56:53 moonpoint sendmail[9659]: v1LCsmdE009658: timeout waiting for input from local during Draining Input
Feb 21 08:24:04 moonpoint sendmail[11738]: v1LDM3HF011737: timeout waiting for input from local during Draining Input
Feb 21 08:26:08 moonpoint sendmail[11792]: v1LDO7T1011791: timeout waiting for input from local during Draining Input
Feb 21 08:59:39 moonpoint sendmail[14394]: v1LDvboE014393: timeout waiting for input from local during Draining Input
Feb 21 09:04:33 moonpoint sendmail[15238]: v1LE2R9M015236: timeout waiting for input from local during Draining Input
Feb 21 09:05:47 moonpoint sendmail[15370]: v1LE3jxC015368: timeout waiting for input from local during Draining Input
Feb 21 09:07:48 moonpoint sendmail[15475]: v1LE5kCi015473: timeout waiting for input from local during Draining Input
Feb 21 09:11:07 moonpoint sendmail[15598]: v1LE95Ma015592: timeout waiting for input from local during Draining Input
Feb 21 09:11:07 moonpoint sendmail[15600]: v1LE95Mb015592: timeout waiting for input from local during Draining Input
Feb 21 09:11:08 moonpoint sendmail[15604]: v1LE95Md015592: timeout waiting for input from local during Draining Input
Feb 21 09:11:09 moonpoint sendmail[15606]: v1LE95Me015592: timeout waiting for input from local during Draining Input
Feb 21 09:17:57 moonpoint sendmail[15899]: v1LEFuoT015898: timeout waiting for input from local during Draining Input
Feb 21 09:45:02 moonpoint sendmail[18027]: v1LEh0lf018026: timeout waiting for input from local during Draining Input
Feb 21 10:04:01 moonpoint sendmail[19640]: v1LF20ir019639: timeout waiting for input from local during Draining Input
Feb 21 10:28:08 moonpoint sendmail[20996]: v1LFQ2Mx020995: timeout waiting for input from local during Draining Input
Feb 21 10:50:50 moonpoint sendmail[22456]: v1LFmmOT022455: timeout waiting for input from local during Draining Input
Feb 21 10:54:54 moonpoint sendmail[22628]: v1LFqrRv022626: timeout waiting for input from local during Draining Input
Feb 21 11:12:57 moonpoint sendmail[24212]: v1LGAtsx024210: timeout waiting for input from local during Draining Input
# grep timeout /var/log/maillog | grep -v grep | wc -l
37
#

I saw an IP address, 117.243.177.152, referenced. When I checked the country for the entity allocated that IP address with geoiplookup, I saw it was India; I wouldn't expect any legitimate email from that location, so it was likely an attempt to send spam.

# geoiplookup 117.243.177.152
GeoIP Country Edition: IN, India
#

Note: you can install the GeoIP package on a CentOS system with yum install geoip.

When I checked the maillog, I saw that spam had been blocked from that IP address.

# grep '117.243.177.152' /var/log/maillog
Feb 21 05:10:22 moonpoint sendmail[31526]: ruleset=check_relay, arg1=[117.243.17
7.152], arg2=127.0.0.15, relay=[117.243.177.152], reject=550 5.7.1 Spam Block:ma
il from 117.243.177.152 refused - see http://dnsbl.sorbs.net/
Feb 21 06:10:27 moonpoint sendmail[31526]: v1LAAMc3031526: timeout waiting for i
nput from [117.243.177.152] during server cmd read
#

But that may have been unrelated to the problem with Dovecot being unresponsive.

I checked the number of dovecot processes again and found the number had climbed to 103.

# ps -aux | grep dovecot | grep -v grep | wc -l
103
#

When I checked the number of connections to Dovecot by IP at the moment with the doveadm who command, I didn't see any.

# doveadm who
username # proto (pids) (ips)
#

I checked to see if Dovecot was configured to log failed password events; it was, since I saw "auth_verbose" was set to "yes". The "auth_verbose_passwords" setting will log the actual password used in failed login attempts - see Dovecot - client connections are being dropped.

# doveconf -a | grep "auth_verbose"
auth_verbose = yes
auth_verbose_passwords = no
#

Since I didn't have time to do any further troubleshooting, I restarted Dovecot at that point. I then used telnet to connect to port 110 again and verified that the user's password was then accepted and that I could use the stat command to see the number of messages in her mailbox; there were 308 messages.

Learning Network Technology and Security
Learning Network Technology and Security
1x1 px

# service dovecot restart
Redirecting to /bin/systemctl restart  dovecot.service
# telnet 127.0.0.1 110
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
+OK Dovecot ready.
user nell
+OK
pass thePassword
+OK Logged in.
stat
+OK 308 42169273
quit
+OK Logging out.
Connection closed by foreign host.
#

Just to be sure that failed POP3 logins were being recorded in the /var/log/maillog file, I used telnet to again connect to port 110, but then entered an incorrect password for an account on the system. I then verified that an entry appeared in the maillog file for that failed password attempt. I noticed that someone else from an IP address in Italy, 92.60.66.18, also attempted to log into the server via POP3 using a nonexistent account on the system just a little over 5 minutes later.

# grep "auth failed" /var/log/maillog
Feb 21 12:34:06 moonpoint dovecot: pop3-login: Aborted login (auth failed, 1 att
empts in 7 secs): user=<bennie>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, sec
ured, session=<zTwMyQ1JwgB/AAAB>
Feb 21 12:39:44 moonpoint dovecot: pop3-login: Aborted login (auth failed, 1 att
empts in 4 secs): user=<bren@moonpoint.com>, method=PLAIN, rip=92.60.66.184, lip
=192.168.5.5, TLS, session=<IiZV3Q1JLQBcPEK4>
# geoiplookup 92.60.66.184
GeoIP Country Edition: IT, Italy
#

I've been encountering this problem periodically with Dovecot stoping responding to connection attempts by users to download their email. E.g., August of last year, but haven't yet determined the root cause of the problem.

Related articles:

  1. Determining the Country Associated with an IP Address
  2. Dovecot - client connections are being dropped
  3. Dovecot not accepting passwords MoonPoint Support