Random behavior with sieve extprograms

[John Stoffel]

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

Thomas> Hi John
Thomas> On 2022-06-01 02:50, John Stoffel wrote:
>>>>>>> "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?

Thomas> "sieve-dabs-execute.sh" is just the socket name. It was a
Thomas> shell script previously and I never updated the socket
Thomas> name. See service sieve-pipe-script in the dovecot -n output.
Thomas> It calls the php script directly: executable = script
Thomas> /usr/bin/php /srv/www/mydomain/status/artisan
Thomas> dabs:processEmail

Thanks for the clarification, I missed that part before.  

Thomas> When testing directly on the cli, it works flawlessly, return
Thomas> code is 0.  bash: php artisan dabs:processEmail < email.file

How about if you run multiple copies of the script at the same time on
the console?  You might be running into contention there.  

Thomas> Here is the handle method of the php script:

Thomas> public function handle()
Thomas>      {
Thomas>          $fd = \fopen('php://stdin', 'rb');

Thomas>          $parser = new MailMimeParser();
Thomas>          $message = $parser->parse($fd, true);

Thomas>          $subject = $message->getHeader(HeaderConsts::SUBJECT);
Thomas>          $dabsDate = \substr(\trim($subject), -11, 8);
Thomas>          $date = \Carbon\Carbon::parse($dabsDate);
Thomas>          $version = \substr($message->getHeader(HeaderConsts::SUBJECT), 
Thomas> -2);

Thomas>          $attachment = $message->getAttachmentPart(0);
Thomas>          $filename = $attachment->getFilename();

Thomas>          if (Storage::exists('/dabs/' . $filename)) {
Thomas>              Log::info('Processing DABS duplicate version: ' . $version . 
Thomas> ' of: ' . $date->format('Y-m-d'));
Thomas>              // increment number to filename
Thomas>              $a = 1;
Thomas>              do {
Thomas>                  $filename_new = \basename($filename, '.pdf') . '_' . $a 
Thomas> . '.pdf';
Thomas>                  $a++;
Thomas>                  if ($a > 9) {
Thomas>                      Log::error('DABS duplicate processing > 9. 
Thomas> Exiting.');
Thomas>                      $this->error('DABS duplicate processing > 9. 
Thomas> Exiting.');
Thomas>                      exit(1);
Thomas>                  }
Thomas>                  $filename = $filename_new;
Thomas>              } while ($this->dabsFileExists($filename_new));
Thomas>          }

Thomas>          Storage::put('/dabs/' . $filename, $attachment->getContent());
Thomas>          $dabs = Dabs::create(
Thomas>              [
Thomas>                  'date' => $date,
Thomas>                  'version' => $version,
Thomas>                  'file' => 'dabs/' . $filename,
Thomas>              ]
Thomas>          );


This part might break because you assume that you're the only
instance of the script running.  You really want to do some locking,
and one way to do that is to try and create a new file in a loop,
since that is an atomic operation.  So in the while loop, once the
Storage::exists call fails, you need to make the file with the
Storage::put, but you need to double check the return value and
continue looping if that file already exists, otherwise you need to
exit and retun the error message (out of disk space, no more inodes,
can't write to file, etc).

With possibly multiple copies of the script running at the same time,
you could be stomping on each other and if you don't handle it
properly, it will do wierd things.  


Thomas>          if ($date->eq(today()) || $date->eq(today()->addDay())) {
Thomas>              event(new DabsReceived($dabs));
Thomas>          }

Thomas>          Log::info('Processing DABS email for DABS version: ' . $version 
Thomas> . ' of: ' . $date->format('Y-m-d'));
Thomas>          sleep(3);
Thomas>          return 0;
Thomas>      }

>> 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've added a 3 second sleep in my php script and will observe.

It might be better to put in a random 3 second sleep, but its hard to
tell.

It might also be simpler to just parse the email with sieve and save
it into a mail file, then run your script on that mailfile once every
five minutes to empty the mailfile and put the emails where you want
them.


Thomas> Could you explain where to add the -vx switch?

If you were still running this all as a shell script, then you'd just
put that at the top, like this:

   #!/bin/sh -xv

or use:

   #!/bin/sh
   set -x
   set -v

to turn on more verbose logging of the shell script and the commands
it rungs.  

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> }