Hello again, all. Of course after posting yesterday that all was well with my setup, turns out all is not well. The problem I'm having is with dovecot-lda functioning and making deliveries to my mailbox, but the sieve scripts don't seem to have any effect. Attempts at logging what is/isn't happening have been total failures.
Managesieve seems to work fine, port 4190 is open on the server and it allows the tunderbird plugin to function, I can create and edit scripts with the plugin. For some reason it doesn't seem to auto-compile the scripts to binary form, but if I just need to do that manually I can live with it. I only mention the lack of auto-compiling in case that sheds light on what is wrong with the LDA or sieve.
I'm running the current dovecot, 2.2.1 along with pigeonhole 0.4.0. Here is the config:
root@hostname:/usr/local/dovecot-2.2.1# doveconf -n # 2.2.1: /usr/local/etc/dovecot/dovecot.conf # OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.0 auth_cache_size = 10 M auth_default_realm = mail.domain.com auth_mechanisms = plain login auth_socket_path = /usr/local/var/run/dovecot/auth-userdb debug_log_path = /dev/stderr default_internal_user = vpopmail default_login_user = vpopmail first_valid_gid = 89 first_valid_uid = 89 hostname = mail.domain.com last_valid_gid = 89 last_valid_uid = 89 lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes log_path = /dev/stderr mail_access_groups = 89 mail_debug = yes mail_gid = 89 mail_location = maildir:%h/Maildir mail_plugins = " quota" mail_privileged_group = 89 mail_uid = 89 managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave spamtest spamtestplus vnd.dovecot.debug namespace inbox { inbox = yes location = prefix = separator = . } passdb { driver = vpopmail } plugin { quota = maildir:User quota quota_rule = *:storage=2G quota_warning = storage=95%% quota-warning 95 %u sieve = ~/.sieve/dovecot.sieve sieve_dir = ~/.sieve sieve_extensions = +spamtest +spamtestplus +relational +comparator-i;ascii-numeric +vnd.dovecot.debug } postmaster_address = postmaster@mail.domain.com protocols = imap pop3 lmtp sieve sendmail_path = /var/qmail/bin/sendmail service auth-worker { user = $default_internal_user } service auth { unix_listener auth-userdb { group = vchkpw mode = 0600 user = vpopmail } user = $default_internal_user } service managesieve-login { inet_listener sieve { port = 4190 } service_count = 1 vsz_limit = 64 M } ssl = required ssl_cert = </var/qmail/control/servercert.pem ssl_key = </var/qmail/control/servercert.priv userdb { args = quota_template=quota_rule=*:backend=%q driver = vpopmail } protocol lda { info_log_path = /dev/stderr log_path = /dev/stderr mail_plugins = " quota sieve" } protocol imap { mail_plugins = " quota imap_quota" } protocol pop3 { mail_plugins = " quota quota" }
I've set the lda specific logs to /dev/stderr because I'm running dovecot through daemontools, and that is what it logs. Daemontools redirects /dev/stderr to /var/log/qmail/qmail-dovecot/current. I had tried logging to /var/log/dovecot/lda.log, that file exists, the directory is 775 dovecot:dovecot, but the file size remained 0. Very little appears in the dovecot logs with lda -
root@hostname:/home/vpopmail/domains/domain.com/jim/.sieve# grep lda /var/log/qmail/qmail-dovecot/current |tai64nlocal 2013-05-16 11:05:49.432026500 May 16 11:05:49 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-16 11:29:32.386361500 May 16 11:29:32 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-16 11:54:03.145741500 May 16 11:54:03 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-16 12:33:40.274543500 May 16 12:33:40 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-16 12:47:07.202036500 May 16 12:47:07 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-16 13:40:44.548948500 May 16 13:40:44 auth: Debug: master in: USER 1jim@domain.com service=lda 2013-05-17 11:50:31.073410500 May 17 11:50:31 auth: Debug: master in: USER 1jim@domain.com service=lda
The sieve issue is as follows: I have a very simple sieve script. the managaesieve utility accepts the script, here is the contents of the $HOME/.sieve directory:
root@hostname:/home/vpopmail/domains/domain.com/jim/.sieve# ls -al total 20 drwx------ 3 vpopmail vchkpw 4096 May 18 02:24 . drwx------ 5 vpopmail vchkpw 4096 May 18 09:39 .. lrwxrwxrwx 1 vpopmail vchkpw 16 May 18 02:22 dovecot.sieve -> night-test.sieve -rw------- 1 vpopmail vchkpw 303 May 18 02:22 dovecot.svbin -rw------- 1 vpopmail vchkpw 315 May 18 02:24 night-test.sieve drwx------ 2 vpopmail vchkpw 4096 May 18 02:24 tmp
The contents of dovecot.sieve itself are:
root@hostname:/home/vpopmail/domains/domain.com/jim/.sieve# cat dovecot.sieve # # 2013-5-17 # require ["fileinto", "envelope", "vnd.dovecot.debug"]; if header :contains ["from"] "sub1.domain.com" { debug_log "match happened and syntax changed for testing purposes"; fileinto "INBOX.folder2"; } else { debug_log "can't catch a cold when wet snowy and cold"; keep; }
The compile of the script works fine as user vpopmail:
vpopmail@hostname:~/domains/domain.com/jim/.sieve$ sievec dovecot.sieve /tmp/dovecot.svbin sievec(vpopmail): Debug: Loading modules from directory: /usr/local/lib/dovecot sievec(vpopmail): Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so sievec(vpopmail): Debug: Effective uid=89, gid=89, home=/home/vpopmail sievec(vpopmail): Debug: Quota root: name=User quota backend=maildir args= sievec(vpopmail): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 sievec(vpopmail): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning 95 vpopmail sievec(vpopmail): Debug: Quota grace: root=User quota bytes=214748364 (10%)
A diff between dovecot.svbin and /tmp/dovecot.svbin shows no difference. Neither of the debug lines show up anywhere in the logs.
When I send an email from sub1.domain.com to this server, it ends up in the main inbox rather than INBOX.folder2. Interestingly, if I run sieve-test on the mail, it tells me it should have been moved to INBOX.folder2:
vpopmail@hostname:~/domains/domain.com/jim/Maildir/cur$ sieve-test ../../.sieve/dovecot.sieve 1368888104.11471.hostname\,S\=1235\:2\,a sieve-test(vpopmail): Debug: Loading modules from directory: /usr/local/lib/dovecot sieve-test(vpopmail): Debug: Module loaded: /usr/local/lib/dovecot/lib10_quota_plugin.so sieve-test(vpopmail): Debug: Effective uid=89, gid=89, home=/home/vpopmail sieve-test(vpopmail): Debug: Quota root: name=User quota backend=maildir args= sieve-test(vpopmail): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 sieve-test(vpopmail): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning 95 vpopmail sieve-test(vpopmail): Debug: Quota grace: root=User quota bytes=214748364 (10%) sieve-test(vpopmail): Debug: Quota root: name=User quota backend=maildir args= sieve-test(vpopmail): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 sieve-test(vpopmail): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning 95 raw mail user sieve-test(vpopmail): Debug: Quota grace: root=User quota bytes=214748364 (10%) sieve-test(vpopmail): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt= dovecot: line 6: info: DEBUG: match happened and syntax changed for testing purposes.
Performed actions:
- store message in folder: INBOX.folder2
Implicit keep:
(none)
sieve-test(vpopmail): Info: final result: success
And yes, INBOX.folder exists:
vpopmail@hostname:~/domains/domain.com/jim/Maildir/cur$ ls -al ../.INBOX.folder2/ total 28 drwx------ 5 vpopmail vchkpw 4096 May 14 10:33 . drwx------ 15 vpopmail vchkpw 4096 May 18 10:42 .. drwx------ 2 vpopmail vchkpw 4096 May 14 10:20 cur -rw------- 1 vpopmail vchkpw 232 May 17 08:07 dovecot.index.log -rw------- 1 vpopmail vchkpw 17 May 14 10:33 dovecot-uidlist -rw------- 1 vpopmail vchkpw 0 May 14 10:20 maildirfolder drwx------ 2 vpopmail vchkpw 4096 May 14 10:20 new drwx------ 2 vpopmail vchkpw 4096 May 14 10:20 tmp
Here's the file that calls dovecot-lda for user jim:
vpopmail@hostname:~/domains/domain.com/jim$ cat .qmail-default |/var/qmail/bin/preline -f /usr/local/libexec/dovecot/dovecot-lda -d $EXT@$USER
Both /var/qmail/bin/preline and /usr/local/libexec/dovecot/dovecot-lda exist.
Any idea why my sieve doesn't seem to take effect?
Thanks for reading.