Sieve redirect does not collect the sendmail child process correctly (Dovecot 2.3.4.1, Pigeonhole 0.5.4)
Stephan Bosch
stephan at rename-it.nl
Sat Nov 2 23:40:45 EET 2019
On 02/11/2019 03:05, Delian Krustev via dovecot wrote:
> Hi,
>
> I got this simple test Sieve config:
>
> #############################################
> # Sieve Filter
> # Generated by Ingo (http://www.horde.org/apps/ingo/) (11/01/2019, 10:46:06 PM)
>
> # Forwards
> if true {
> redirect "krustev at krustev.net";
> }
> # Forward Keep Action
> if true {
> keep;
> stop;
> }
> #############################################
>
>
> Which used to work fine with:
>
> # 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf
> # Pigeonhole version 0.4.16 (fed8554)
> # OS: Linux 4.9.0-8-amd64 x86_64 Debian 9.11
>
> Then I've tried migrating to:
>
> # 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf
> # Pigeonhole version 0.5.4 ()
> # OS: Linux 4.19.0-6-amd64 x86_64 Debian 10.1
>
> And started getting the following errors:
>
> # cat .dovecot.sieve.log
> sieve: info: started log at Nov 01 22:55:50.
> error: msgid=<4221584.AlbrL4BjWX at home>: failed to redirect message to <krustev at krustev.net>: Failed to execute sendmail (temporary failure).
I think we already know about this issue (tracked as DOP-942). It
apparently happens because qmail masks the SIGCHLD signal while Dovecot
doesn't unmask it before waiting for children.
Regards,
Stephan.
>
> A google search lead me to:
>
> https://bugs.archlinux.org/task/56933
>
> which blames systemd service changes:
>
> NoNewPrivileges=true
>
> , however I'm not running dovecot via systemd but use DJB's daemontools for
> service supervision .
>
> The page above suggested to change from:
>
> sendmail_path = /usr/sbin/sendmail
>
> to
>
> submission_host = localhost
>
> in "conf.d/15-lda.conf", which worked fine.
> But since I don't have other problems with "sendmail" execution I've decided
> to debug this further.
>
> I have dovecot integrated with Qmail:
>
> # apt-cache policy qmail
> qmail:
> Installed: 1.06-6+b1
> Candidate: 1.06-6+b1
> Version table:
> *** 1.06-6+b1 900
> 900 http://deb.debian.org/debian buster/main amd64 Packages
>
> so sendmail's implementation comes from Qmail:
>
> # ls -al `which sendmail`
> lrwxrwxrwx 1 root root 14 Feb 23 2015 /usr/sbin/sendmail -> qmail-sendmail
>
>
> I've strace-d the qmail-lspawn process which executes dovecot's LDA, which
> processes the Sieve rules and executes "sendmail".
> The sendmail process executes and returns successfully, the mail is delivered,
> however the Sieve code does not wait for the child process correctly and tries
> to kill the already exited process after 30 seconds timeout.
>
> Here are the problematic Sieve syscalls:
>
> 22:55:15.283482 execve("/usr/lib/dovecot/deliver", ["/usr/lib/dovecot/deliver", "-e", "-a", "tester at krustev.net"], 0x5620b4330c40 /* 61 vars */) = 0
> ...
> 22:55:15.286845 pipe([5, 6]) = 0
> 22:55:15.286870 fcntl(5, F_GETFL) = 0 (flags O_RDONLY)
> 22:55:15.286889 fcntl(5, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
> 22:55:15.286909 fcntl(6, F_GETFL) = 0x1 (flags O_WRONLY)
> 22:55:15.286928 fcntl(6, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
> 22:55:15.286947 fcntl(5, F_GETFD) = 0
> 22:55:15.286966 fcntl(5, F_SETFD, FD_CLOEXEC) = 0
> 22:55:15.286985 fcntl(6, F_GETFD) = 0
> 22:55:15.287003 fcntl(6, F_SETFD, FD_CLOEXEC) = 0
> 22:55:15.287024 epoll_create(128) = 7
> 22:55:15.287043 fcntl(7, F_GETFD) = 0
> 22:55:15.287062 fcntl(7, F_SETFD, FD_CLOEXEC) = 0
> 22:55:15.287084 epoll_ctl(7, EPOLL_CTL_ADD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47201248, u64=94699781110752}}) = 0
> ...
> 22:55:15.294625 epoll_ctl(7, EPOLL_CTL_DEL, 5, 0x7ffd59156b8c) = 0
> 22:55:15.294647 epoll_create(128) = 12
> 22:55:15.294668 fcntl(12, F_GETFD) = 0
> 22:55:15.294687 fcntl(12, F_SETFD, FD_CLOEXEC) = 0
> 22:55:15.294708 epoll_ctl(12, EPOLL_CTL_ADD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47455536, u64=94699781365040}}) = 0
>
> Dovecot/Sieve will wait for this pipe FD 5 later, but no event will arrive.
>
> 22:55:15.294740 rt_sigaction(SIGCHLD, {sa_handler=0x7f15404b3640, sa_mask=[], sa_flags=SA_RESTORER|SA_RESTART|SA_SIGINFO, sa_restorer=0x7f1540229840}, NULL, 8) = 0
> 22:55:15.294763 pipe([13, 14]) = 0
> 22:55:15.294788 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f15401ec2d0) = 6929
>
>
> The sendmail child process with PID 6929 is forked here.
>
>
> 22:55:15.294928 close(13) = 0
> 22:55:15.294969 fcntl(14, F_GETFL) = 0x1 (flags O_WRONLY)
> 22:55:15.295006 fcntl(14, F_SETFL, O_WRONLY|O_NONBLOCK) = 0
> 22:55:15.295039 lseek(14, 0, SEEK_CUR) = -1 ESPIPE (Illegal seek)
> 22:55:15.295065 getsockname(14, 0x7ffd59156a40, [28]) = -1 ENOTSOCK (Socket operation on non-socket)
> 22:55:15.295109 write(14, "EDITTED LONG MESSAGE DATA\n", 1461) = 1461
> 22:55:15.295150 close(14) = 0
> 22:55:15.295175 wait4(6929, 0x562102d4fee4, WNOHANG, NULL) = 0
> 22:55:15.295211 epoll_wait(12, [], 1, 30000) = 0
>
>
> Here's where the 30 second's timeout is requested and waited.
>
>
> 22:55:45.325580 kill(6929, SIGTERM) = 0
> 22:55:45.325769 epoll_wait(12, [], 1, 5000) = 0
> 22:55:50.331108 kill(6929, SIGKILL) = 0
> 22:55:50.332867 wait4(6929, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 6929
> 22:55:50.333020 epoll_ctl(12, EPOLL_CTL_DEL, 5, 0x7ffd59156b6c) = 0
> 22:55:50.333060 epoll_ctl(7, EPOLL_CTL_ADD, 5, {EPOLLIN|EPOLLPRI|EPOLLERR|EPOLLHUP, {u32=47201248, u64=94699781110752}}) = 0
> 22:55:50.333097 close(12) = 0
> 22:55:50.333240 sendto(9, "<19>Nov 1 22:55:50 dovecot: lda(krustev)<6926><IlpXEdO3vF0OGwAA4EGeoA>: Error: sieve: msgid=<4221584.AlbrL4BjWX at home>: failed to redirect message to <krustev at krustev.net>: Failed to execute sendmail (temporary failure)", 220, MSG_NOSIGNAL, NULL, 0) = 220
> 22:55:50.333321 openat(AT_FDCWD, "/home/krustev/mail/domains/krustev.net/tester/.dovecot.sieve.log", O_WRONLY|O_CREAT|O_APPEND, 0600) = 12
> 22:55:50.333557 fstat(12, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
> 22:55:50.333613 lseek(12, 0, SEEK_CUR) = 0
> 22:55:50.333643 fstat(12, {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
> 22:55:50.333678 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=127, ...}) = 0
> 22:55:50.333726 write(12, "sieve: info: started log at Nov 01 22:55:50.\n", 45) = 45
> 22:55:50.333788 write(12, "error: msgid=<4221584.AlbrL4BjWX at home>: failed to redirect message to <krustev at krustev.net>: Failed to execute sendmail (temporary failure).\n", 141) = 141
> 22:55:50.333857 sendto(9, "<19>Nov 1 22:55:50 dovecot: lda(krustev)<6926><IlpXEdO3vF0OGwAA4EGeoA>: Error: sieve: Execution of script /home/krustev/mail/domains/krustev.net/tester/.dovecot.sieve was aborted due to temporary failure (user logfile /home/krustev/mail/domains/krustev.net/tester/.dovecot.sieve.log may reveal additional details)", 317, MSG_NOSIGNAL, NULL, 0) = 317
> 22:55:50.333941 close(10) = 0
> 22:55:50.333996 close(12) = 0
> 22:55:50.334057 lstat("/home/krustev/mail/domains/krustev.net/tester/.dovecot.lda-dupes.lock", {st_mode=S_IFREG|0600, st_size=0, ...}) = 0
> 22:55:50.334095 unlink("/home/krustev/mail/domains/krustev.net/tester/.dovecot.lda-dupes.lock") = 0
> 22:55:50.334188 close(11) = 0
> 22:55:50.334245 write(2, "Execution of Sieve filters was aborted due to temporary failure\n", 64) = 64
> 22:55:50.334418 munmap(0x7f15401bc000, 103680) = 0
> 22:55:50.334481 munmap(0x7f15403b3000, 32800) = 0
> 22:55:50.334516 munmap(0x7f15400fb000, 788352) = 0
> 22:55:50.334610 epoll_ctl(7, EPOLL_CTL_DEL, 8, 0x7ffd5915706c) = 0
> 22:55:50.334640 close(8) = 0
> 22:55:50.334685 epoll_ctl(7, EPOLL_CTL_DEL, 5, 0x7ffd5915706c) = 0
> 22:55:50.334738 close(5) = 0
> 22:55:50.334785 close(6) = 0
> 22:55:50.334813 close(7) = 0
> 22:55:50.334841 close(4) = 0
> 22:55:50.334881 exit_group(75) = ?
> 22:55:50.335077 +++ exited with 75 +++
>
>
> Here's the interesting part of sendmail's (PID 6929) execution with timestamps:
> ..
> 22:55:15.295268 execve("/usr/sbin/sendmail", ["/usr/sbin/sendmail", "-i", "-f", "tester at krustev.net", "--", "krustev at krustev.net"], NULL) = 0
> ...
> 22:55:15.296024 chdir("/var/lib/qmail") = 0
> 22:55:15.296055 execve("bin/qmail-inject", ["bin/qmail-inject", "-a", "-f", "tester at krustev.net", "--", "krustev at krustev.net"], 0x55741b1890e0 /* 2 vars */) = 0
> ...
> 22:55:15.297264 vfork() = 6930
> ..
> 22:55:15.297930 wait4(6930, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0, NULL) = 6930
> 22:55:15.305391 exit_group(0) = ?
> 22:55:15.305472 +++ exited with 0 +++
>
> The PID 6930 is a call to the setuid qmail-queue, which also executes and returns normally.
>
>
> With all the above stated - It seems that the problem is in the "epoll" calls.
> Either it is not set-up correctly or dovecot-LDA does not receive the
> information it waits for.
>
> I've tried to make my way trough Dovecot's source code but have concluded that
> someone more familiar should be able to spot the problem much quicker than me.
>
>
> Let me know if you need some additional information.
> Sorry for the long mail.
>
>
>
> Dovecot config follows:
>
> # 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf
> # Pigeonhole version 0.5.4 ()
> # OS: Linux 4.19.0-6-amd64 x86_64 Debian 10.1
> # Hostname: pinko.livehostserver.com
> auth_mechanisms = plain login
> disable_plaintext_auth = no
> lda_mailbox_autocreate = yes
> lda_mailbox_autosubscribe = yes
> log_path = /dev/stderr
> log_timestamp =
> mail_plugins = " quota"
> 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 index ihave duplicate mime foreverypart extracttext
> namespace inbox {
> inbox = yes
> location =
> mailbox Archive {
> special_use = \Archive
> }
> mailbox Archives {
> special_use = \Archive
> }
> mailbox "Deleted Items" {
> special_use = \Trash
> }
> mailbox "Deleted Messages" {
> special_use = \Trash
> }
> mailbox Drafts {
> auto = subscribe
> special_use = \Drafts
> }
> mailbox Junk {
> auto = subscribe
> special_use = \Junk
> }
> mailbox "Junk E-mail" {
> special_use = \Junk
> }
> mailbox Sent {
> auto = subscribe
> special_use = \Sent
> }
> mailbox "Sent Items" {
> special_use = \Sent
> }
> mailbox "Sent Mail" {
> special_use = \Sent
> }
> mailbox "Sent Messages" {
> special_use = \Sent
> }
> mailbox Spam {
> special_use = \Junk
> }
> mailbox Trash {
> auto = subscribe
> special_use = \Trash
> }
> mailbox sent-mail {
> special_use = \Sent
> }
> prefix =
> }
> passdb {
> args = /usr/local/sbin/vchkpw-dovecot
> driver = checkpassword
> }
> plugin {
> antispam_allow_append_to_spam = yes
> antispam_backend = pipe
> antispam_pipe_program = /bin/sh
> antispam_pipe_program_notspam_args = -c;HOME=$PWD exec nice sa-learn --ham
> antispam_pipe_program_spam_args = -c;HOME=$PWD exec nice sa-learn --spam
> antispam_pipe_tmpdir = /tmp
> antispam_spam_pattern_ignorecase = spam;junk;junk *
> antispam_trash_pattern_ignorecase = trash;Deleted *
> quota = maildir:User quota
> sieve = ~/.dovecot.sieve
> sieve_dir = ~/sieve
> sieve_redirect_envelope_from = recipient
> }
> protocols = " imap sieve pop3"
> service anvil {
> client_limit = 1536
> }
> service auth {
> client_limit = 1536
> }
> service imap-login {
> process_limit = 512
> }
> service managesieve-login {
> inet_listener sieve {
> port = 4190
> }
> process_min_avail = 1
> service_count = 1
> }
> service managesieve {
> process_limit = 50
> }
> service pop3-login {
> process_limit = 512
> }
> service stats {
> client_limit = 1024
> unix_listener stats-writer {
> mode = 0666
> }
> }
> ssl_ca = </scm/deb-global/etc/ssl/intermediate-CAs.crt
> ssl_cert = </etc/ssl/default-fullchain.pem
> ssl_client_ca_dir = /etc/ssl/certs
> ssl_dh = # hidden, use -P to show it
> ssl_key = # hidden, use -P to show it
> userdb {
> driver = prefetch
> }
> protocol lda {
> info_log_path =
> log_path =
> mail_plugins = " quota sieve"
> }
> protocol imap {
> mail_max_userip_connections = 64
> mail_plugins = " quota imap_quota antispam"
> }
> protocol sieve {
> mail_max_userip_connections = 10
> managesieve_implementation_string = Dovecot Pigeonhole
> managesieve_max_line_length = 65536
> }
>
>
> Best regards
> --
> Delian
More information about the dovecot
mailing list