Hello,
Today while looking at a different issue (one user couldn't retrieve
mail; DNS issue) I set 'mail_debug=yes' then ran `dovecot reload` on our
mail server. After running the reload, dovecot started complaning about
permission issues with the dict file, and preceded to try to kill it's
self. The self reload didn't seem to work, and since this is a
production system, I was forced to restart the dovecot service. After
the restart of the service, everything seemed to go back to normal.
Dovecot is currently working as expected, no other permission errors in
the logs.
Dovecot Version: 2.0.9 (3582271a897e) running on Fedora 14 running with
a mySQL setup including dict tables (quota, expire). The virtual user's
mail has a local user and group id of 1000.
Below is the expert from the log:
Jan 25 18:00:01 milly postfix/smtpd[9418]: connect from
odin.example.com[174.143.172.159]
Jan 25 18:00:01 milly postfix/smtpd[9418]: disconnect from
odin.example.com[174.143.172.159]
Jan 25 18:01:05 milly dovecot: dict: mysql: Connected to localhost (postfix)
Jan 25 18:01:17 milly dovecot: master: Warning: SIGHUP received - reloading
configuration
Jan 25 18:01:27 milly postfix/anvil[6470]: statistics: max connection rate 2/60s
for (submission:192.168.10.12) at Jan 25 17:57:19
Jan 25 18:01:27 milly postfix/anvil[6470]: statistics: max connection count 1
for (smtp:168.100.1.4) at Jan 25 17:52:25
Jan 25 18:01:27 milly postfix/anvil[6470]: statistics: max cache size 3 at Jan
25 17:55:23
Jan 25 18:01:59 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:01:59 milly dovecot: imap(matt): Error: Internal quota calculation
error
Jan 25 18:02:02 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:02:02 milly dovecot: imap(matt): Error: Internal quota calculation
error
Jan 25 18:02:14 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:02:14 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:02:14 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:02:14 milly dovecot: imap(matt): Error:
net_connect_unix(/usr/var/run/dovecot/dict) failed: Permission denied
(euid=1000(virtualmail) egid=1000(virtualmail) missing +r perm:
/usr/var/run/dovecot/dict, euid is not dir owner)
Jan 25 18:02:17 milly dovecot: master: Warning: Processes aren't dying after
reload, sending SIGTERM.
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=73545/124557
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=9609/127653
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=2836/8394
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=9335/53756
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=2449/6084
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=1000/2416
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=52000/12276
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=3796/86595
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=557/2333
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=2003/6833
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=60624/207831
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=103883/195056
Jan 25 18:02:17 milly dovecot: imap: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: imap: Server shutting down. bytes=68919/371893
Jan 25 18:02:17 milly dovecot: config: Warning: Killed with signal 15 (by
pid=5922 uid=0 code=kill)
Jan 25 18:02:17 milly dovecot: dict: Warning: Killed with signal 15 (by pid=5922
uid=0 code=kill)
( I manually restarted the dovecot service )
Jan 25 18:03:09 milly dovecot: lda: Debug: Loading modules from directory:
/usr/lib/dovecot/
Jan 25 18:03:09 milly dovecot: lda: Debug: Module loaded:
/usr/lib/dovecot//lib10_quota_plugin.so
Jan 25 18:03:09 milly dovecot: lda: Debug: Module loaded:
/usr/lib/dovecot//lib20_expire_plugin.so
Jan 25 18:03:09 milly dovecot: lda: Debug: Module loaded:
/usr/lib/dovecot//lib90_sieve_plugin.so
Jan 25 18:03:09 milly dovecot: auth: mysql: Connected to localhost (postfix)
Jan 25 18:03:09 milly dovecot: lda: Debug: auth input: lists maildir=lists
uid=1000 gid=1000 home=/var/spool/virtualmailboxes/lists
quota_rule=*:storage=4194304 mail=mdbox:/var/spool/virtualmailboxes/lists
Jan 25 18:03:09 milly dovecot: lda: Debug: changed username to lists
Jan 25 18:03:09 milly dovecot: lda: Debug: Added userdb setting:
plugin/maildir=lists
Jan 25 18:03:09 milly dovecot: lda: Debug: Added userdb setting:
plugin/quota_rule=*:storage=4194304
Jan 25 18:03:09 milly dovecot: lda: Debug: Added userdb setting:
mail=mdbox:/var/spool/virtualmailboxes/lists
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Effective uid=1000, gid=1000,
home=/var/spool/virtualmailboxes/lists
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota root: name=User quota
backend=dict args=:proxy::quota
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=* bytes=4294967296 messages=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=Trash bytes=+858993459 (20%) messages=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=Junk bytes=+858993459 (20%) messages=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: dict quota: user=lists,
uri=proxy::quota, noenforcing=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Namespace : type=private,
prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes
location=mdbox:/var/spool/virtualmailboxes/lists
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: fs:
root=/var/spool/virtualmailboxes/lists, index=, control=, inboxJan 25 18:03:09
milly dovecot: lda(lists): Debug: Namespace : Using permissions from
/var/spool/virtualmailboxes/lists: mode=0700 gid=-1
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Namespace : type=shared,
prefix=shared/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no
location=maildir:%h/
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: shared:
root=/usr/var/run/dovecot, index=, control=, inboxJan 25 18:03:09 milly dovecot:
lda(lists): Debug: Namespace : type=public, prefix=Public/, sep=/, inbox=no,
hidden=no, list=yes, subscriptions=yes
location=mdbox:/var/spool/virtualmailboxes//public
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: fs:
root=/var/spool/virtualmailboxes//public, index=, control=, inboxJan 25 18:03:09
milly dovecot: lda(lists): Debug: Namespace Public/: Using permissions from
/var/spool/virtualmailboxes//public: mode=0700 gid=-1
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota root: name=User quota
backend=dict args=:proxy::quota
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=* bytes=1073741824 messages=100000
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=Trash bytes=+214748364 (20%) messages=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: Quota rule: root=User quota
mailbox=Junk bytes=+214748364 (20%) messages=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: dict quota: user=lists at
example.com, uri=proxy::quota, noenforcing=0
Jan 25 18:03:09 milly dovecot: lda(lists): Debug: none: root=, index=, control=,
inbox
I can provide my doveconf -n output and any other info you may need.
Thanks
-Matt
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 5425 bytes
Desc: S/MIME Cryptographic Signature
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20110125/1a5c04df/attachment-0002.bin>