2010/10/15 Timo Sirainen tss@iki.fi:
On Fri, 2010-10-15 at 13:47 +0100, Timo Sirainen wrote:
But you should have seen in logs at login time stuff like:
Debug: Namespace : type=shared, prefix=shared/%d/%n/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=maildir:%h/Maildir:INDEX=~/shared-index
I added some more stuff that gets logged now with mail_debug=yes and could be helpful in figuring out why shared mailboxes don't work:
http://hg.dovecot.org/dovecot-2.0/rev/b277b71fb57f http://hg.dovecot.org/dovecot-2.0/rev/b0e4edc4d79a
Sorry for the late reply. Was not in the office.
Dovecot used /var.log/debug as the debug logfile. I edit the dovecot.conf file, and now it logs all to /var/log/maillog.
i did the following again, telnet 192.168.50.200 143 Trying 192.168.50.200... Connected to beasty.double-l.local. Escape character is '^]'. this is what i get in the logs.
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready. a login johan@domain.com johanpass a OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA ACL RIGHTS=texk] Logged in b GETACL b BAD Error in IMAP command GETACL: Missing arguments b GETACL INBOX
- ACL "INBOX" "hans@domain.com" lr "johan@domain.com" lrwstipekxacd b OK Getacl completed. ^] telnet> quit Connection closed. beasty log # telnet 192.168.50.200 143 Trying 192.168.50.200... Connected to beasty.double-l.local. Escape character is '^]'.
- OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE AUTH=PLAIN AUTH=LOGIN] Dovecot ready. a login hans@domain.com hanspass a OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS MULTIAPPEND UNSELECT IDLE CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS QUOTA ACL RIGHTS=texk] Logged in b list "" shared/* b OK List completed. c list "" shared/domain.com/johan/* c OK List completed. d select shared/domain.com/johan/INBOX d NO Mailbox doesn't exist: shared/domain.com/johan/INBOX ^] telnet> quit Connection closed.
Oct 18 14:22:29 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Oct 18 14:22:29 auth: Debug: auth client connected (pid=98928) Oct 18 14:22:49 auth: Debug: client in: AUTH 1 PLAIN service=imap secured lip=192.168.50.200 rip=192.168.50.200 lport=143 rport=33182 resp=AGpvaGFuQGRvbWFpbi5jb20Aam9oYW5wYXNz Oct 18 14:22:49 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Oct 18 14:22:49 auth: Info: mysql: Connected to localhost (postfix) Oct 18 14:22:49 auth: Debug: sql(johan@domain.com,192.168.50.200): query: select password from mailbox where username = 'johan@domain.com' and active = '1' Oct 18 14:22:49 auth: Debug: client out: OK 1 user=johan@domain.com Oct 18 14:22:49 auth: Debug: master in: REQUEST 1 98928 1 48479282aecab3b1b82306981b2c7b1b Oct 18 14:22:49 auth: Debug: sql(johan@domain.com,192.168.50.200): select maildir, concat('*:messages=50000:bytes=', quota) as quota_rule from mailbox where username = 'johan@domain.com' and active = '1' Oct 18 14:22:49 auth: Debug: master out: USER 1 johan@domain.com maildir=domain.com/johan/ quota_rule=*:messages=50000:bytes=1024000000 Oct 18 14:22:49 imap-login: Info: Login: user=johan@domain.com, method=PLAIN, rip=192.168.50.200, lip=192.168.50.200, mpid=99091, secured Oct 18 14:22:49 imap: Debug: Loading modules from directory: /usr/local/lib/dovecot Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib01_acl_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib02_imap_acl_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib11_imap_quota_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib15_notify_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib20_autocreate_plugin.so Oct 18 14:22:49 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib20_mail_log_plugin.so Oct 18 14:22:49 imap: Debug: Added userdb setting: plugin/maildir=domain.com/johan/ Oct 18 14:22:49 imap: Debug: Added userdb setting: plugin/quota_rule=*:messages=50000:bytes=1024000000 Oct 18 14:22:49 imap(johan@domain.com): Debug: Effective uid=1004, gid=1004, home= Oct 18 14:22:49 imap(johan@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:22:49 imap(johan@domain.com): Debug: Quota rule: root= mailbox=* bytes=1024000000 messages=50000 Oct 18 14:22:49 imap(johan@domain.com): Debug: Quota warning: bytes=972800000 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:22:49 imap(johan@domain.com): Debug: Quota warning: bytes=819200000 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:22:49 imap(johan@domain.com): Debug: dict quota: user=johan@domain.com, uri=proxy::quotadict, noenforcing=0 Oct 18 14:22:49 imap(johan@domain.com): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/usr/local/virtual/domain.com/johan Oct 18 14:22:49 imap(johan@domain.com): Debug: maildir++: root=/usr/local/virtual/domain.com/johan, index=, control=, inbox=/usr/local/virtual/domain.com/johan Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: acl username = johan@domain.com Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: owner = 1 Oct 18 14:22:49 imap(johan@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:22:49 imap(johan@domain.com): Debug: Namespace : type=shared, prefix=shared/%d/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=maildir:/usr/local/virtual/%d/%n/shared/:INDEX=/shared/%d/%n Oct 18 14:22:49 imap(johan@domain.com): Debug: shared: root=/var/run/dovecot, index=, control=, inbox= Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: acl username = johan@domain.com Oct 18 14:22:49 imap(johan@domain.com): Debug: acl: owner = 0 Oct 18 14:22:49 imap(johan@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:22:49 imap(johan@domain.com): Debug: Namespace : Using permissions from /usr/local/virtual/domain.com/johan: mode=0700 gid=-1 Oct 18 14:23:28 imap(johan@domain.com): Debug: acl vfile: reading file /usr/local/virtual/domain.com/johan/dovecot-acl Oct 18 14:23:28 imap(johan@domain.com): Debug: acl vfile: reading file /usr/local/virtual/domain.com/johan/dovecot-acl Oct 18 14:25:45 imap(johan@domain.com): Info: Connection closed bytes=26/455 Oct 18 14:25:48 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Oct 18 14:25:48 auth: Debug: auth client connected (pid=629) Oct 18 14:26:00 auth: Debug: client in: AUTH 1 PLAIN service=imap secured lip=192.168.50.200 rip=192.168.50.200 lport=143 rport=34472 resp=AGhhbnNAZG9tYWluLmNvbQBoYW5zcGFzcw== Oct 18 14:26:00 auth: Debug: Loading modules from directory: /usr/local/lib/dovecot/auth Oct 18 14:26:00 auth: Info: mysql: Connected to localhost (postfix) Oct 18 14:26:00 auth: Debug: sql(hans@domain.com,192.168.50.200): query: select password from mailbox where username = 'hans@domain.com' and active = '1' Oct 18 14:26:00 auth: Debug: client out: OK 1 user=hans@domain.com Oct 18 14:26:00 auth: Debug: master in: REQUEST 1 629 1 4b4d31b52569246bde5ab9457e5fa36d Oct 18 14:26:00 auth: Debug: sql(hans@domain.com,192.168.50.200): select maildir, concat('*:messages=50000:bytes=', quota) as quota_rule from mailbox where username = 'hans@domain.com' and active = '1' Oct 18 14:26:00 auth: Debug: master out: USER 1 hans@domain.com maildir=domain.com/hans/ quota_rule=*:messages=50000:bytes=102400000 Oct 18 14:26:00 imap-login: Info: Login: user=hans@domain.com, method=PLAIN, rip=192.168.50.200, lip=192.168.50.200, mpid=730, secured Oct 18 14:26:00 imap: Debug: Loading modules from directory: /usr/local/lib/dovecot Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib01_acl_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib02_imap_acl_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib11_imap_quota_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib15_notify_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib20_autocreate_plugin.so Oct 18 14:26:00 imap: Debug: Module loaded: /usr/local/lib/dovecot/lib20_mail_log_plugin.so Oct 18 14:26:00 imap: Debug: Added userdb setting: plugin/maildir=domain.com/hans/ Oct 18 14:26:00 imap: Debug: Added userdb setting: plugin/quota_rule=*:messages=50000:bytes=102400000 Oct 18 14:26:00 imap(hans@domain.com): Debug: Effective uid=1004, gid=1004, home= Oct 18 14:26:00 imap(hans@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:26:00 imap(hans@domain.com): Debug: Quota rule: root= mailbox=* bytes=102400000 messages=50000 Oct 18 14:26:00 imap(hans@domain.com): Debug: Quota warning: bytes=97280000 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:26:00 imap(hans@domain.com): Debug: Quota warning: bytes=81920000 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:26:00 imap(hans@domain.com): Debug: dict quota: user=hans@domain.com, uri=proxy::quotadict, noenforcing=0 Oct 18 14:26:00 imap(hans@domain.com): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/usr/local/virtual/domain.com/hans Oct 18 14:26:00 imap(hans@domain.com): Debug: maildir++: root=/usr/local/virtual/domain.com/hans, index=, control=, inbox=/usr/local/virtual/domain.com/hans Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: acl username = hans@domain.com Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: owner = 1 Oct 18 14:26:00 imap(hans@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:26:00 imap(hans@domain.com): Debug: Namespace : type=shared, prefix=shared/%d/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=maildir:/usr/local/virtual/%d/%n/shared/:INDEX=/shared/%d/%n Oct 18 14:26:00 imap(hans@domain.com): Debug: shared: root=/var/run/dovecot, index=, control=, inbox= Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: acl username = hans@domain.com Oct 18 14:26:00 imap(hans@domain.com): Debug: acl: owner = 0 Oct 18 14:26:00 imap(hans@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:26:00 imap(hans@domain.com): Debug: Namespace : Using permissions from /usr/local/virtual/domain.com/hans: mode=0700 gid=-1 Oct 18 14:26:06 beasty postfix/qmgr[13582]: 18D833F494: from=johan@schavemaker.com, size=324, nrcpt=1 (queue active) Oct 18 14:26:06 lda: Debug: Loading modules from directory: /usr/local/lib/dovecot Oct 18 14:26:06 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib01_acl_plugin.so Oct 18 14:26:06 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so Oct 18 14:26:06 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib15_notify_plugin.so Oct 18 14:26:06 lda: Debug: Module loaded: /usr/local/lib/dovecot/lib20_mail_log_plugin.so Oct 18 14:26:06 auth: Debug: master in: USER 1 johan@domain.com service=lda Oct 18 14:26:06 auth: Debug: sql(johan@domain.com): select maildir, concat('*:messages=50000:bytes=', quota) as quota_rule from mailbox where username = 'johan@domain.com' and active = '1' Oct 18 14:26:06 auth: Debug: master out: USER 1 johan@domain.com maildir=domain.com/johan/ quota_rule=*:messages=50000:bytes=1024000000 Oct 18 14:26:06 lda: Debug: auth input: johan@domain.com maildir=domain.com/johan/ quota_rule=*:messages=50000:bytes=1024000000 Oct 18 14:26:06 lda: Debug: Added userdb setting: plugin/maildir=domain.com/johan/ Oct 18 14:26:06 lda: Debug: Added userdb setting: plugin/quota_rule=*:messages=50000:bytes=1024000000 Oct 18 14:26:06 lda(johan@domain.com): Debug: Effective uid=1004, gid=1004, home= Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota rule: root= mailbox=* bytes=1024000000 messages=50000 Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota warning: bytes=972800000 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota warning: bytes=819200000 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:26:06 lda(johan@domain.com): Debug: dict quota: user=johan@domain.com, uri=proxy::quotadict, noenforcing=0 Oct 18 14:26:06 lda(johan@domain.com): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/usr/local/virtual/domain.com/johan Oct 18 14:26:06 lda(johan@domain.com): Debug: maildir++: root=/usr/local/virtual/domain.com/johan, index=, control=, inbox=/usr/local/virtual/domain.com/johan Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: acl username = johan@domain.com Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: owner = 1 Oct 18 14:26:06 lda(johan@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:26:06 lda(johan@domain.com): Debug: Namespace : type=shared, prefix=shared/%d/%u/, sep=/, inbox=no, hidden=no, list=children, subscriptions=no location=maildir:/usr/local/virtual/%d/%n/shared/:INDEX=/shared/%d/%n Oct 18 14:26:06 lda(johan@domain.com): Debug: shared: root=/var/run/dovecot, index=, control=, inbox= Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: acl username = johan@domain.com Oct 18 14:26:06 lda(johan@domain.com): Debug: acl: owner = 0 Oct 18 14:26:06 lda(johan@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:26:06 lda(johan@domain.com): Debug: Quota warning: bytes=0 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:26:06 lda(johan@domain.com): Debug: dict quota: user=johan@domain.com, uri=proxy::quotadict, noenforcing=0 Oct 18 14:26:06 lda(johan@domain.com): Debug: none: root=, index=, control=, inbox= Oct 18 14:26:06 dict: Info: mysql: Connected to localhost (postfix) Oct 18 14:26:06 lda(johan@domain.com): Info: save: box=INBOX, uid=2, msgid=20101018121703.18D833F494@mailserver.schavemaker.com, size=384 Oct 18 14:26:06 lda(johan@domain.com): Info: msgid=20101018121703.18D833F494@mailserver.schavemaker.com: saved mail to INBOX Oct 18 14:26:06 beasty postfix/pipe[787]: 18D833F494: to=johan@domain.com, relay=dovecot, delay=544, delays=544/0.02/0/0.03, dsn=2.0.0, status=sent (delivered via dovecot service) Oct 18 14:26:06 beasty postfix/qmgr[13582]: 18D833F494: removed Oct 18 14:27:51 dict: Error: sql dict iterate: Invalid/unmapped path: shared/shared-boxes/anyone/ Oct 18 14:27:51 dict: Info: mysql: Connected to localhost (postfix) Oct 18 14:27:51 imap(hans@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:27:51 imap(hans@domain.com): Debug: Quota rule: root= mailbox=* bytes=102400000 messages=50000 Oct 18 14:27:51 imap(hans@domain.com): Debug: Quota warning: bytes=97280000 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:27:51 imap(hans@domain.com): Debug: Quota warning: bytes=81920000 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:27:51 imap(hans@domain.com): Debug: dict quota: user=johan@domain.com, uri=proxy::quotadict, noenforcing=0 Oct 18 14:27:51 imap(hans@domain.com): Debug: maildir++: root=/usr/local/virtual/domain.com/johan/shared, index=/shared/domain.com/johan, control=, inbox=/usr/local/virtual/domain.com/johan/shared Oct 18 14:27:51 imap(hans@domain.com): Debug: Namespace shared/domain.com/johan@domain.com/: Permission lookup failed from /usr/local/virtual/domain.com/johan/shared Oct 18 14:27:51 imap(hans@domain.com): Debug: Namespace shared/domain.com/johan@domain.com/: Using permissions from /usr/local/virtual/domain.com/johan/shared: mode=0700 gid=-1 Oct 18 14:27:51 imap(hans@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:27:51 imap(hans@domain.com): Debug: acl: acl username = hans@domain.com Oct 18 14:27:51 imap(hans@domain.com): Debug: acl: owner = 0 Oct 18 14:27:51 imap(hans@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:27:51 imap(hans@domain.com): Debug: acl vfile: file /usr/local/virtual/domain.com/johan/shared/dovecot-acl not found Oct 18 14:28:54 imap(hans@domain.com): Debug: Quota root: name= backend=dict args=:proxy::quotadict Oct 18 14:28:54 imap(hans@domain.com): Debug: Quota rule: root= mailbox=* bytes=102400000 messages=50000 Oct 18 14:28:54 imap(hans@domain.com): Debug: Quota warning: bytes=97280000 (95%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 95 Oct 18 14:28:54 imap(hans@domain.com): Debug: Quota warning: bytes=81920000 (80%) messages=0 reverse=no command=/usr/local/bin/quota-warning.sh 80 Oct 18 14:28:54 imap(hans@domain.com): Debug: dict quota: user=johan, uri=proxy::quotadict, noenforcing=0 Oct 18 14:28:54 imap(hans@domain.com): Debug: maildir++: root=/usr/local/virtual//johan/shared, index=/shared//johan, control=, inbox=/usr/local/virtual//johan/shared Oct 18 14:28:54 imap(hans@domain.com): Debug: acl: initializing backend with data: vfile Oct 18 14:28:54 imap(hans@domain.com): Debug: acl: acl username = hans@domain.com Oct 18 14:28:54 imap(hans@domain.com): Debug: acl: owner = 0 Oct 18 14:28:54 imap(hans@domain.com): Debug: acl vfile: Global ACL directory: (null) Oct 18 14:28:54 imap(hans@domain.com): Debug: acl vfile: file /usr/local/virtual//johan/shared/dovecot-acl not found Oct 18 14:29:04 imap(hans@domain.com): Info: Connection closed bytes=97/410
regards, Johan Hendriks