[Dovecot] dovecot/log not running
Mark Hinch
mhinch at hinchfamily.com
Wed Sep 12 14:13:55 EEST 2012
Answers for both my helpers - Timo and Ben (Thanks!):
Timo: Problem #1 - no dovecot/login
doveconf -n output:
==============
# 2.1.7: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.30-2-686 i686 Debian wheezy/sid
mail_access_groups = mail
mail_location = mbox:~/mail:INBOX=/var/mail/%n
mail_privileged_group = mail
namespace inbox {
inbox = yes
location =
prefix =
}
passdb {
driver = pam
}
plugin {
mail_log_events = delete undelete expunge copy mailbox_delete
mailbox_rename
mail_log_fields = uid box msgid size
}
protocols = " imap"
ssl_cert = </etc/ssl/certs/dovecot.pem
ssl_key = </etc/ssl/private/dovecot.pem
userdb {
driver = passwd
}
============================
I don't see anything interesting there -- hopefully you do!
BTW - dovecot/log is still not running. However, to deepen the mystery,
yesterday I suddenly found it to be running and to be dumping stuff into
my log file.
Closer examination using "ps" showed that while dovecot was restarted
(via a cronjob
to work around problem #2)) at 01:30 (i.e., at around 1am), dovecot/log
started running at 17:12 (i.e., around 5pm).
This is confirmed in the log files (i.e., no log output until 5pm). The
dovecot logs are:
=======================
Sep 10 01:30:02 hinch4 dovecot: master: Dovecot v2.1.7 starting up (core
dumps disabled)
Sep 10 01:30:42 hinch4 dovecot: master: Error: service(anvil): Initial
status notification not received in 30 seconds, killing the p
rocess
Sep 10 01:30:42 hinch4 dovecot: master: Error: service(log): Initial
status notification not received in 30 seconds, killing the pro
cess
Sep 10 01:30:42 hinch4 dovecot: master: Error: service(ssl-params):
Initial status notification not received in 30 seconds, killing
the process
Sep 10 01:30:42 hinch4 dovecot: master: Error: service(log): child 3505
killed with signal 9
Sep 10 08:14:11 hinch4 dovecot: master: Error: service(imap-login):
Initial status notification not received in 30 seconds, killing
the process
Sep 10 17:12:44 hinch4 dovecot: log: Error: Received master input for
invalid service_fd 24: 24 3504 FATAL service(anvil): child 350
4 killed with signal 9
Sep 10 17:12:44 hinch4 dovecot: log: Error: Received master input for
invalid service_fd 24: 24 3504 BYE
Sep 10 17:12:44 hinch4 dovecot: master: Error: service(log): child 23736
killed with signal 11 (core dumps disabled)
Sep 10 17:12:44 hinch4 dovecot: imap(mhinch): Debug: Effective uid=1002,
gid=1002, home=/home/mhinch
Sep 10 17:12:44 hinch4 dovecot: imap(mhinch): Debug: Namespace inbox:
type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, s
ubscriptions=yes location=mbox:~/mail:INBOX=/var/mail/mhinch
Sep 10 17:12:44 hinch4 dovecot: imap(mhinch): Debug: fs:
root=/home/mhinch/mail, index=, control=, inbox=/var/mail/mhinch, alt=
========================
many more logging messages deleted. This continued until I restarted
dovecot. Never again
have I seen a log message ...
Bob: Problem #2 - many doncecot/imap-login processes:
The Thunderbird setting for "connection to cache" is 5. The setting of
100 is on
the server side as default_process_limit.
However, the 5 is interesting. That seems to say that tbird has forgotten
about all but 5 (max). I'll try to catch lsof -i output on these rogue
processes
to see what IP state they are in. Any other ideas about where to go?
Thanks!
-Mark
On 9/11/2012 11:23 AM, Timo Sirainen wrote:
> Something's very wrong. I have no idea what. doveconf -n output might help.
>
> On 7.9.2012, at 14.39, Mark Hinch wrote:
>
>> I'm running 2.1.7 as downloaded/installed by Debian (and
>> then appropriately setup for my config, ...). It almost
>> works. I can send/receive email from thunderbird, squirrelmail, ...
>> However there are two anomalies:
>> 1. dovecot/log is not running. After restarting dovecot (and waiting
>> 30 seconds), I have this in the log files:
>>
>> Sep 6 17:42:16 hinch4 dovecot: master: Dovecot v2.1.7 starting up (core dumps disabled)
>> Sep 6 17:42:56 hinch4 dovecot: master: Error: service(anvil): Initial status notification not received in 30 seconds, killing the process
>> Sep 6 17:42:56 hinch4 dovecot: master: Error: service(log): Initial status notification not received in 30 seconds, killing the process
>> Sep 6 17:42:56 hinch4 dovecot: master: Error: service(ssl-params): Initial status notification not received in 30 seconds, killing the process
>> Sep 6 17:42:56 hinch4 dovecot: master: Error: service(log): child 31286 killed with signal 9
>>
>> After 30 seconds, a "ps -ef | grep dovecot" yields:
>>
>> dovenull 1858 20223 0 18:56 ? 00:00:00 dovecot/imap-login
>> root 1859 20223 0 18:56 ? 00:00:00 dovecot/auth -w
>> mhinch 1860 20223 0 18:56 ? 00:00:00 dovecot/imap
>> root 1862 14520 0 18:56 pts/3 00:00:00 grep dovecot
>> root 20223 1 0 18:54 ? 00:00:00 /usr/sbin/dovecot -c /etc/dovecot/dovecot.conf
>> dovenull 25144 20223 0 18:55 ? 00:00:00 dovecot/imap-login
>> dovecot 25147 20223 0 18:55 ? 00:00:00 dovecot/anvil
>> root 25148 20223 0 18:55 ? 00:00:00 dovecot/config
>> dovecot 25161 20223 0 18:55 ? 00:00:00 dovecot/auth
>> root 25174 20223 0 18:55 ? 00:00:00 dovecot/ssl-params
>> mhinch 25208 20223 0 18:55 ? 00:00:00 dovecot/imap
>>
>> Seems like everything is there except dovecot/log. ssl-params and anvil came back (?!?).
>> A "doveadm log find" dumps this in the log:
>> Sep 6 18:52:24 hinch4 dovecot: doveadm: Debug: This is Dovecot's debug log (1346975543)
>> Sep 6 18:52:24 hinch4 dovecot: doveadm: This is Dovecot's info log (1346975543)
>> Sep 6 18:52:24 hinch4 dovecot: doveadm: Warning: This is Dovecot's warning log (1346975543)
>> Sep 6 18:52:24 hinch4 dovecot: doveadm: Error: This is Dovecot's error log (1346975543)
>> Sep 6 18:52:24 hinch4 dovecot: doveadm: Fatal: This is Dovecot's fatal log (1346975543)
>>
>> However, further debugging that I try to do (see next problem) does not result in ANY
>> further input to the log files, even though I have all known logging turned on. So I *think*
>> that logging is not actually running. If I can get that started, then I'll take a crack at the
>> next problem myself ...
>>
>> 2. However, as long as I have your attention, my next problem is that it
>> seems like dovecot/imap-login hangs(?). After a few hours, I have something like:
>>
>> # ps -ef | grep dovecot
>> dovecot 530 31186 0 18:49 ? 00:00:00 dovecot/auth
>> root 13277 31186 0 17:47 ? 00:00:00 dovecot/config
>> dovenull 13664 31186 0 18:44 ? 00:00:00 dovecot/imap-login
>> root 20207 14520 0 18:54 pts/3 00:00:00 grep dovecot
>> dovenull 27599 31186 0 18:45 ? 00:00:00 dovecot/imap-login
>> dovenull 27601 31186 0 18:45 ? 00:00:00 dovecot/imap-login
>> dovenull 27603 31186 0 18:45 ? 00:00:00 dovecot/imap-login
>> dovenull 27607 31186 0 18:45 ? 00:00:00 dovecot/imap-login
>> root 31186 1 0 17:42 ? 00:00:00 /usr/sbin/dovecot -c /etc/dovecot/dovecot.conf
>> dovecot 31289 31186 0 17:42 ? 00:00:00 dovecot/anvil
>>
>> with exactly 100 imap-login processes. I'm the only meaningful user
>> on the machine (unless somebody is imap DoS-ing me), so this does not
>> make much sense. Obviously thunderbird is polling the machine and each
>> time is leaving around a imap-log process. As far as I can tell, thunderbird
>> successfully logs in (i.e., I get mail) though I can't be sure whether these
>> are successful logins or not (no logging!). What hangs imap-log processes for hours at a time?
>> After a while of course, dovecot will not start any new imap-login processes
>> so Thunderbird cannot get any more mail until I restart
>> dovecot. Then everything is OK for another 12 hours or so.
>>
>> Ideas on either problem?
>>
>> -Mark
>>
More information about the dovecot
mailing list