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=, inbox= Jan 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=, inbox= Jan 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=, inbox= Jan 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@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