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.
# 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.
# 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:
