Random behavior with sieve extprograms

Wed Jun 1 00:50:37 UTC 2022

>>>>> "Thomas" == Thomas Sommer <ts-2016 at flightsupport.ch> writes:

Thomas> I have a random behavior with dovecot and sieve extprograms.

Thomas> Here is my sieve file:
Thomas> require ["fileinto", "vnd.dovecot.pipe", "copy", "imap4flags"];
Thomas> # rule:[DABS]
Thomas> if header :contains "X-Original-To" "dabs at mydomain.ch"
Thomas> {
Thomas> 	pipe "sieve-dabs-execute.sh";
Thomas> 	setflag "\\Seen";
Thomas> 	fileinto "acme.DABS";
Thomas> 	stop;
Thomas> }

Can you post the code of this script?  Are you trapping all exceptions
in that script and making sure you only return errors when there
really is an error?  

Thomas> Emails matching the condition are processed by a laravel (php) artisan 
Thomas> command. See service sieve-pipe-script below.
Thomas> The exit code of this php command is 0.

You are calling the php command from a shell script, so there's
multiple places things could go wrong.  Why not just pipe directly to
the php script (which wasn't included unless I'm totally blind and
dumb tonight... :-) instead?

It honestly sounds like a timing issue, maybe just putting a sleep
into your shell script at the end would be good?  Or maybe run with
the -vx switches so you log all the commands and their results?  

Thomas> I randomly get the following in my postfix logs:
Thomas> Sieve thinks that the command failed, but the email was always processed 
Thomas> correctly. In that case I get a copy in my Inbox.
Thomas> I'm wondering what could be the cause for this random behavior.
Thomas> My guess is that approximately 70% are processed correctly, 30% is as 
Thomas> below.

Thomas> May 31 13:50:38 star dovecot[99425]: 
Thomas> lda(user)<99425><kma+MC4dlmJhhAEAzJBnyA>: sieve: 
Thomas> msgid=<62961d1c.5y4hr0Vqi97JFnyb%DABS.zsmsvp02 at example.com>: fileinto 
Thomas> action: stored mail into mailbox 'acme.DABS'
Thomas> May 31 13:50:39 star dovecot[99425]: 
Thomas> lda(user)<99425><kma+MC4dlmJhhAEAzJBnyA>: sieve: 
Thomas> msgid=<62961d1c.5y4hr0Vqi97JFnyb%DABS.zsmsvp02 at example.com>: stored mail 
Thomas> into mailbox 'INBOX'
Thomas> May 31 13:50:39 star dovecot[99425]: 
Thomas> lda(user)<99425><kma+MC4dlmJhhAEAzJBnyA>: sieve: Execution of script 
Thomas> /home/user/sieve/.dovecot.sieve failed, but implicit keep was successful 
Thomas> (user logfile /home/user/sieve/.dovecot.sieve.log may reveal additional 
Thomas> details)

Thomas> .dovecot.sieve.log:
Thomas> sieve: info: started log at May 31 13:50:39.
Thomas> error: failed to pipe message to program `sieve-dabs-execute.sh': refer 
Thomas> to server log for more information. [2022-05-31 13:50:39].

Thomas> It's weird. "failed to pipe message to program" is simply not true. The 
Thomas> command was processed correctly.

Thomas> Any ideas where to look for clues or how to debug this?

Thomas> Regards
Thomas> Thomas

Thomas> config:

Thomas> # 2.3.14 (cee3cbc0d): /etc/dovecot/dovecot.conf
Thomas> # Pigeonhole version 0.5.14 (1b5c82b2)
Thomas> # OS: Linux 5.17.5-x86_64-linode154 x86_64 Ubuntu 20.04.4 LTS
Thomas> auth_mechanisms = plain login
Thomas> auth_username_format = %n
Thomas> auth_verbose = yes
Thomas> mail_location = maildir:~/Maildir
Thomas> mail_plugins = " quota"
Thomas> managesieve_notify_capability = mailto
Thomas> managesieve_sieve_capability = fileinto reject envelope 
Thomas> encoded-character vacation subaddress comparator-i;ascii-numeric 
Thomas> relational regex imap4flags copy include variables body enotify 
Thomas> environment mailbox date index ihave duplicate mime foreverypart 
Thomas> extracttext vnd.dovecot.pipe vnd.dovecot.execute
Thomas> namespace inbox {
Thomas>    inbox = yes
Thomas>    location =
Thomas>    mailbox Drafts {
Thomas>      special_use = \Drafts
Thomas>    }
Thomas>    mailbox Junk {
Thomas>      special_use = \Junk
Thomas>    }
Thomas>    mailbox Sent {
Thomas>      special_use = \Sent
Thomas>    }
Thomas>    mailbox "Sent Messages" {
Thomas>      special_use = \Sent
Thomas>    }
Thomas>    mailbox Trash {
Thomas>      special_use = \Trash
Thomas>    }
Thomas>    prefix =
Thomas> }
Thomas> passdb {
Thomas>    driver = pam
Thomas> }
Thomas> plugin {
Thomas>    quota = fs:User quota
Thomas>    quota_grace = 1%%
Thomas>    quota_status_nouser = DUNNO
Thomas>    quota_status_overquota = 552 5.2.2 Mailbox is full
Thomas>    quota_status_success = DUNNO
Thomas>    sieve = file:~/sieve;active=~/sieve/.dovecot.sieve
Thomas>    sieve_execute_socket_dir =
Thomas>    sieve_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute
Thomas>    sieve_pipe_exec_timeout = 30s
Thomas>    sieve_pipe_socket_dir =
Thomas>    sieve_plugins = sieve_extprograms
Thomas>    sieve_redirect_envelope_from = recipient
Thomas>    sieve_trace_debug = no
Thomas>    sieve_trace_dir = ~/sieve/trace
Thomas>    sieve_trace_level = matching
Thomas> }
Thomas> protocols = imap sieve
Thomas> service auth {
Thomas>    unix_listener /var/spool/postfix/private/dovecot-auth {
Thomas>      group = postfix
Thomas>      mode = 0660
Thomas>      user = postfix
Thomas>    }
Thomas> }
Thomas> service quota-status {
Thomas>    client_limit = 1
Thomas>    executable = /usr/lib/dovecot/quota-status -p postfix
Thomas>    inet_listener {
Thomas>      address = 127.0.0.1
Thomas>      port = 8881
Thomas>    }
Thomas> }
Thomas> service sieve-pipe-script {
Thomas>    executable = script /usr/bin/php /srv/www/mydomain/status/artisan 
Thomas> dabs:processEmail
Thomas>    unix_listener sieve-dabs-execute.sh {
Thomas>      mode = 0660
Thomas>      user = user
Thomas>    }
Thomas>    user = www-data
Thomas>    vsz_limit = 512 M
Thomas> }
Thomas> ssl = required
Thomas> ssl_cert = </etc/letsencrypt/live/star.mydomain.ch/fullchain.pem
Thomas> ssl_cipher_list = AES128+EECDH:AES128+EDH
Thomas> ssl_client_ca_dir = /etc/ssl/certs
Thomas> ssl_dh = # hidden, use -P to show it
Thomas> ssl_key = # hidden, use -P to show it
Thomas> ssl_min_protocol = TLSv1.2
Thomas> ssl_prefer_server_ciphers = yes
Thomas> userdb {
Thomas>    driver = passwd
Thomas> }
Thomas> protocol lda {
Thomas>    deliver_log_format = msgid=%m: %$
Thomas>    mail_plugins = " quota sieve"
Thomas>    postmaster_address = postmaster at mydomain.ch
Thomas>    quota_full_tempfail = yes
Thomas>    rejection_reason = Your message to <%t> was automatically 
Thomas> rejected:%n%r
Thomas> }
Thomas> protocol imap {
Thomas>    mail_max_userip_connections = 20
Thomas>    mail_plugins = " quota mail_log notify imap_quota"
Thomas> }