[Dovecot] Permissions issues after dovecot reload

Wed Jan 26 02:48:23 EET 2011

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 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-0001.bin 