[Dovecot] Dovecot 2.2.1 LDA and sieve (lack of) errors
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 = :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.
On 5/18/2013 4:56 PM, Jim McNamara wrote:
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
mail_debug = yes
So, mail_debug is enabled.
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.
Are you sure this is actually being executed? What happens if you execute dovecot-lda manually?
This is an example of what you're supposed to see in the logs with mail_debug=yes:
May 18 23:28:02 klara dovecot: lda: Debug: Loading modules from directory: /usr/lib/dovecot/modules May 18 23:28:02 klara dovecot: lda: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so May 18 23:28:02 klara dovecot: lda(stephan): Debug: Effective uid=1000, gid=1000, home=/home/stephan May 18 23:28:02 klara dovecot: lda(stephan): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir May 18 23:28:02 klara dovecot: lda(stephan): Debug: maildir++: root=/home/stephan/Maildir, index=, indexpvt=, control=, inbox=/home/stephan/Maildir, alt= May 18 23:28:02 klara dovecot: lda(stephan): Debug: userdb lookup skipped, username taken from USER environment May 18 23:28:02 klara dovecot: lda(stephan): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt= May 18 23:28:02 klara dovecot: lda(stephan): Debug: Destination address: stephan@klara (source: user@hostname) May 18 23:28:02 klara dovecot: lda(stephan): Debug: sieve: Pigeonhole version 0.4.0 initializing
Regards,
Stephan.
On 05/18/2013 05:35 PM, Stephan Bosch wrote:
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
mail_debug = yes
So, mail_debug is enabled.
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.
Are you sure this is actually being executed? What happens if you execute dovecot-lda manually?
I found that LDA was not being executed from the user's .qmail-default file, I changed that file to call a non-existent delivery agent, and the message still ended up in the inbox, not sorted as it should have been, so vpopmail was still handling the delivery. This is a qmail issue, simply renaming .qmail-default to .qmail in that user's vpopmail directory allowed lda to begin functioning.
This is an example of what you're supposed to see in the logs with mail_debug=yes:
May 18 23:28:02 klara dovecot: lda: Debug: Loading modules from directory: /usr/lib/dovecot/modules May 18 23:28:02 klara dovecot: lda: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so May 18 23:28:02 klara dovecot: lda(stephan): Debug: Effective uid=1000, gid=1000, home=/home/stephan May 18 23:28:02 klara dovecot: lda(stephan): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir May 18 23:28:02 klara dovecot: lda(stephan): Debug: maildir++: root=/home/stephan/Maildir, index=, indexpvt=, control=, inbox=/home/stephan/Maildir, alt= May 18 23:28:02 klara dovecot: lda(stephan): Debug: userdb lookup skipped, username taken from USER environment May 18 23:28:02 klara dovecot: lda(stephan): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt= May 18 23:28:02 klara dovecot: lda(stephan): Debug: Destination address: stephan@klara (source: user@hostname) May 18 23:28:02 klara dovecot: lda(stephan): Debug: sieve: Pigeonhole version 0.4.0 initializing
Regards,
Stephan.
Now this is interesting - I do have Pigeonhole and sieve enabled according to doveconf -n, but the only mention of sieve is as a subdirectory of the user's home, no mention of the sieve module at all. I do see that Pigeonhole 0.4.0 is enabled. Also, there have only been 0 mentions of lda in the current dovecot log, and that log is 6 hours old.
I'll try running dovecot-lda manually after checking out the man page.
Thanks again for the help!
On 05/18/2013 07:32 PM, Jim McNamara wrote:
On 05/18/2013 05:35 PM, Stephan Bosch wrote: Now this is interesting - I do have Pigeonhole and sieve enabled according to doveconf -n, but the only mention of sieve is as a subdirectory of the user's home, no mention of the sieve module at all. I do see that Pigeonhole 0.4.0 is enabled. Also, there have only been 0 mentions of lda in the current dovecot log, and that log is 6 hours old.
I'll try running dovecot-lda manually after checking out the man page.
Thanks again for the help!
Turns out again it was a qmail issue - the dovecot logs didn't contain any sieve info because for my install's point of view, sieving was the last step of qmail send, so there was a subdirectory of difference. Here's the massive verbose log of one message, you see the plugin loaded and everything is finally behaving. Thanks again for the help and insight Stephan, I appreciate your time. If you're in NYC sometime, I owe you a drink!
2013-05-21 08:20:40.761051500 delivery 129452: success: May_21_08:20:40_lda:_Debug:_Loading_modules_from_directory:_/usr/local/lib/dovecot/May_21_08:20:40_lda:_Debug:_Module_loaded:_/usr/local/lib/dovecot/lib10_quota_plugin.so/May_21_08:20:40_lda:_Debug:_Module_loaded:_/usr/local/lib/dovecot/lib90_sieve_plugin.so/May_21_08:20:40_lda:_Debug:_auth_input:_jim@domain.com_uid=89_gid=89_home=/home/vpopmail/domains/domain.com/jim_quota_rule=*:backend=2000000000S/May_21_08:20:40_lda:_Debug:_Added_userdb_setting:_plugin/quota_rule=*:backend=2000000000S/May_21_08:20:40_lda(jim@domain.com):_Debug:_Effective_uid=89,_gid=89,_home=/home/vpopmail/domains/domain.com/jim/May_21_08:20:40_lda(jim@domain.com):_Debug:_quota:_No_quota_setting_-_plugin_disabled/May_21_08:20:40_lda(jim@domain.com):_Debug:_Namespace_inbox:_type=private,_prefix=,_sep=.,_inbox=yes,_hidden=no,_list=yes,_subscriptions=yes_location=maildir:/home/vpopmail/domains/domain.com/jim/Maildir/May_21_08:20:40_lda(jim@domain.com):_Debug:_maildir++:_root=/home/vpopmail/domains/domain.com/jim/Maildir,_index=,_indexpvt=,_control=,_inbox=/home/vpopmail/domains/domain.com/jim/Maildir,_alt=/May_21_08:20:40_lda(jim@domain.com):_Debug:_quota:_No_quota_setting_-_plugin_disabled/May_21_08:20:40_lda(jim@domain.com):_Debug:_none:_root=,_index=,_indexpvt=,_control=,_inbox=,_alt=/May_21_08:20:40_lda(jim@domain.com):_Debug:_Destination_address:_jim@domain.com_(source:_user@hostname)/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_Pigeonhole_version_0.4.0_initializing/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_include:_sieve_global_dir_is_not_set;_it_is_currently_not_possible_to_include_`:global'_scripts./May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_script_file_/home/vpopmail/domains/domain.com/jim/.sieve/dovecot.sieve_not_found/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_user's_script_~/.sieve/dovecot.sieve_doesn't_exist_(using_default_script_location_instead)/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_using_the_following_location_for_user's_Sieve_script:_/usr/local/etc/dovecot/sieve/default.sieve;name=main_script/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_loading_script_/usr/local/etc/dovecot/sieve/default.sieve;name=main_script/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_script_binary_/usr/local/etc/dovecot/sieve/default.svbin_successfully_loaded/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_binary_save:_not_saving_binary_/usr/local/etc/dovecot/sieve/default.svbin,_because_it_is_already_stored/May_21_08:20:40_lda(jim@domain.com):_Debug:_sieve:_executing_script_from_/usr/local/etc/dovecot/sieve/default.svbin/May_21_08:20:40_lda(jim@domain.com):_Info:_sieve:_msgid=E1UelXV-0004Nf-7R@sub1.domain.com:_stored_mail_into_mailbox_'INBOX.nagios.folder2'/did_0+0+1/
participants (2)
-
Jim McNamara
-
Stephan Bosch