Large number of procmail processes and failing POP3 connections

I was notified by a user that she was not able to check her email. After verifying that I could successfully establish a Telnet connection to the Simple Mail Transfer Protocol (SMTP) port, i.e., well-known port 25, which her system would use for sending email, I then tried establishing a Post Office Protocol version 3 (POP3) connection to the mail server from an external Microsoft Windows system, using Microsoft's telnet client. But that got stuck at "connecting to".
Microsoft Telnet> open mail.example.com 110
Connecting To mail.example.com...

So I logged into the mail server, which is a CentOS 7 Linux server running Sendmail and Dovecot, and tried connecting to the localhost address, 127.0.0.1, but Dovecot never responded with a banner, nor did I receive any response when I issued a user command to provide login credentials. I had to hit Ctrl-] to exit from the Telnet program, since I wasn't getting any response from Dovecot.

Aiseesoft Video Converter Ultimate
# telnet 127.0.0.1 110
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
user lila
^]
telnet> quit
Connection closed.
#

I checked the system's mail log, but saw no references to dovecot nor pop3 in the day's log.

# grep dovecot /var/log/maillog
# grep pop3 /var/log/maillog
#

When I checked on the Dovecot processes that were running, I saw a very large number of such processes.

# ps -aux | grep dovecot
dovenull   346  0.0  0.1  45272  3248 ?        S    19:40   0:00 dovecot/pop3-login
dovenull   421  0.0  0.1  45140  3252 ?        S    19:41   0:00 dovecot/pop3-login
dovenull   837  0.0  0.1  45140  3252 ?        S    19:50   0:00 dovecot/pop3-login
root       893  0.0  0.0  12524   904 ?        S    13:02   0:00 dovecot/pop3
root       901  0.0  0.0  12524   908 ?        S    13:02   0:00 dovecot/pop3
root      1189  0.0  0.0  12524   908 ?        S    06:00   0:00 dovecot/pop3

When I counted the number of "dovecot/pop3" and "dovecot/pop3-login" processes, I saw 32 instances of the latter process, 76 instances of the former process and 112 total for all processes containing "dovecot".

# ps -aux | grep "dovecot/pop3-login" | wc -l
32
# ps -aux | grep "dovecot/pop3" | grep -v "login" | wc -l
76
# ps -aux | grep dovecot | wc -l
112

Since, while reviewing the maillog file, I also saw references to "timeout waiting for input from local during Draining Input", I counted the number of such instances and found 127 of them.

# grep "Draining" /var/log/maillog | wc -l
127
#

While checking on the possible cause of those messages, I found [CentOS] Re: Sendmail: timeout waiting for input from local during Draining Input. The person posting noted he could resolve the problem he was experiencing by stopping and restarting Dovecot "every so often", but that wasn't a good solution for him nor would it be for me. Someone who responded stated "You need to make sure that all three processes are using the same lock type, with sendmail V8.13 is fcntl. Sometimes I see dovecot defaults with flock enabled, and it could be causing the lock contentions. Also make sure that you didn't somehow enable dovecot's deliver while procmail is still enabled."

I found the Sendmail version was 8.14. I checked to see what locking mechanism Dovecot was using and found it to be fnctl.

# doveconf -d | grep -i lock
dotlock_use_excl = yes
lock_method = fcntl
mail_max_lock_timeout = 0
mbox_dotlock_change_timeout = 2 mins
mbox_lock_timeout = 5 mins
mbox_read_locks = fcntl
mbox_write_locks = dotlock fcntl
pop3_lock_session = no

When I checked on procmail processes running with ps aux | grep procmail, I found many (well over one hundred) like the following:

son.Thelma@geotermic.org -t -Y -a  -d ann
ann      31687  0.0  0.0  15896   896 ?        Ss   Dec01   0:00 procmail -f RebeccaMorgan@pick.facedxh.top -t -Y -a  -d ann
ann      31826  0.0  0.0  15896  1068 ?        Ss   12:51   0:00 procmail -f PermanentlyEliminateNeuropathy@breathless.ohysend.top -t -Y -a  -d ann
ann      32418  0.0  0.0  15896   900 ?        Ss   Dec01   0:00 procmail -f PANSY.AYRTON@euro-tara.su -t -Y -a  -d ann
ann      32686  0.0  0.0  15896  1060 ?        Ss   19:37   0:00 procmail -f StarShower@8aggryn.club -t -Y -a  -d ann

All but one were related to one user's account, though that wasn't the user who reported the email issue.

I restarted Dovecot with the command service dovecot restart, I was then able to connect to check the users mailbox by establishing a connection to the POP3 port, port 110. I was then able to see that she had 387 messages in her mailbox by issuing the stat command after issuing the user and pass commands to provide her login credentials.

# telnet 127.0.0.1 110
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
+OK Dovecot ready.
user lila
+OK
pass thePassword
+OK Logged in.
stat
+OK 387 18824992
quit
+OK Logging out.
Connection closed by foreign host.
#

When I ran the mailq command to check on queued email, I saw 72 queued messages. A lot of messages had an asterick after the queue ID, which indicates a lock exists for the message. There were a lot of what appeared to be spam messages queued for delivery. The spam messages had a "to" address that corresponded to an email alias address on the system that results in email being delivered to two local accounts, but also some external email addresses on other domains. The queued messages were bound for those external email addresses.

# mailq
                /var/spool/mqueue (72 requests)
-----Q-ID----- --Size-- -----Q-Time----- ------------Sender/Recipient-----------
uB1NZe2Q012982*    1651 Thu Dec  1 18:43 <santas-shop-emersons=example02.com@cro
          7BIT   (host map: lookup (crosbystillsnashyoung.com): deferred)
                                         <emersons@example02.com>
uB32fTer015234     4002 Fri Dec  2 21:41 MAILER-DAEMON
                                         <leise.sonya-emersons=example02.com@ji
uB32adBk024633*    3848 Fri Dec  2 21:36 MAILER-DAEMON
                 (Deferred: Name server: smtp.atlanticbb.net: host name lookup)
                                         <sandy-mcglathery-emersons=example02.c
uB32fLFZ030925     4039 Fri Dec  2 21:41 MAILER-DAEMON
                                         <elaine.pavao-emersons=example02.com@j
uB32fWVb029492     4042 Fri Dec  2 21:41 MAILER-DAEMON
                                         <charlotte-corbi-emersons=example02.co
uB32euDV021491     4083 Fri Dec  2 21:40 MAILER-DAEMON
                                         <christa-patera-emersons=example02.com
uB32fGhW014824     5415 Fri Dec  2 21:41 MAILER-DAEMON
                                         <military_flashlight-emersons=example0
uB32fLKt003888     5590 Fri Dec  2 21:41 MAILER-DAEMON
                                         <russian-dating-emersons=example02.com
uB32a3LK017017     5459 Fri Dec  2 21:36 MAILER-DAEMON
                 (Deferred: Name server: smtp.atlanticbb.net: host name lookup)
                                         <debt-restructure-team-emersons=exampl
uB32eqoa025429     5830 Fri Dec  2 21:40 MAILER-DAEMON
                                         <business_phone_systems-emersons=examp
<text snipped>
                Total requests: 72
#

The files associated with queued messages are stored in the /var/spool/mqueue directory. E.g., for the second queued message above there is a "df" and a "qf" file:

# ls /var/spool/mqueue/*uB32fTer015234
/var/spool/mqueue/dfuB32fTer015234  /var/spool/mqueue/qfuB32fTer015234

You can delete a queue entry by removing both of them - see Deleting the files associated with a mailq entry. The "df" file contains the contents of the email. You can examine the "qf" file to see the "from", "to", and "subject" lines, though you may also see them in the "df" file.

# rm /var/spool/mqueue/*uB32fTer015234
rm: remove regular file /var/spool/mqueue/dfuB32fTer015234? y
rm: remove regular file /var/spool/mqueue/qfuB32fTer015234? y
#

I removed several of the queued spam messages, but then had to go to bed because it was late at night by the time I started cleaning up the queue. When I checked the mail queue again the next day, there were no messages remaining in the mail queue. Nor were there any procmail processes running. And there were no "timeout waiting for input from local during Draining Input" entries in this day's maillog file. There were only 4 Dovecot processes running.

# mailq
/var/spool/mqueue is empty
                Total requests: 0
# 
# ps aux | grep procmail | grep -v grep
# grep "Draining" /var/log/maillog | wc -l
0
# ps -aux | grep dovecot | grep -v grep | wc -l
4
# ps -aux | grep dovecot | grep -v grep
root     10793  0.0  0.0  40284  1224 ?        Ss   Dec02   0:00 /usr/sbin/dovecot -F
dovecot  10876  0.0  0.0   9312   580 ?        S    Dec02   0:00 dovecot/anvil
root     14755  0.0  0.1  12328  2020 ?        S    20:39   0:00 dovecot/config
dovecot  14756  0.0  0.0  29916  1844 ?        S    20:39   0:00 dovecot/auth
#

So, at this point, I suspect the queued spam is related to the issue with Dovecot not responding to user's email client queries, but I still don't know what was the original cause of the problem. I've had to restart Dovecot several times over the last few months, e.g., I noted a similar problem in Dovecot - client connections are being dropped on July 4 when I found 101 "dovecot/pop3-login" processes running on the mail server, which led me to check on the configuration of Dovecot. But yesterday's problem was dissimilar from the incident on July 4, since when I checked the maillog file for yesterday for "dovecot" entries again today, the only ones I found were for ones where I restarted Dovecot.

oreilly.com - Your tech ebook super store
# grep dovecot /var/log/maillog.1 | wc -l
6
# grep dovecot /var/log/maillog.1
Dec  2 21:34:29 example dovecot: master: Warning: Killed with signal 15 (by pid=
1 uid=0 code=kill)
Dec  2 21:34:33 example dovecot: master: Dovecot v2.2.10 starting up for imap, p
op3, lmtp (core dumps disabled)
Dec  2 21:35:14 example dovecot: master: Error: service(anvil): Initial status n
otification not received in 30 seconds, killing the process
Dec  2 21:35:14 example dovecot: master: Error: service(log): Initial status not
ification not received in 30 seconds, killing the process
Dec  2 21:35:14 example dovecot: master: Error: service(ssl-params): Initial sta
tus notification not received in 30 seconds, killing the process
Dec  2 21:35:14 example dovecot: master: Error: service(log): child 10872 killed
 with signal 9
#

On July 4, I found lots of dovecot "process _limit (100) reached" entries, but no such entries in yesterday's log files.

# grep limit /var/log/maillog.1
#

 

Firstrade newegg.com

Justdeals Daily Electronics Deals1x1 px