Random behavior with sieve extprograms

[Thomas Sommer]

After adding the sleep(3) in my php script, I observed the processing 
the last couple of days.
At first it seemed fixed, but today it happened again.

Same story: sieve: Execution of script failed.
But again, the script ran correctly.

I ran the following test over the last 250 emails I received:
#!/bin/bash
set -x
set -v

find ./tests/Dabs -type f -name '*' -exec sh -c '
   for file do
     echo "$file"
     php artisan dabs:processEmail < $file --env=dabs
     echo Exit code: $?
   done
' exec-sh {} +

Exit code of the script is always 0.

I don't think it a locking issue as there are only 4 emails each day... 
and the script above runs at a much faster pace... I ran the test 
without the sleep(3).

Any other ideas?

Thanks
Thomas

On 2022-06-01 20:48, John Stoffel wrote:
>>>>>> "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> }