Re: Random behavior with sieve extprograms

Hi John

On 2022-06-01 02:50, John Stoffel wrote:

...

...

...

...

...

"Thomas" == Thomas Sommer ts-2016@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@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?

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

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

Here is the handle method of the php script:

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

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

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

-2);

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

     if (Storage::exists('/dabs/' . $filename)) {
         Log::info('Processing DABS duplicate version: ' . $version . 

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

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

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

     Log::info('Processing DABS email for DABS version: ' . $version 

. ' of: ' . $date->format('Y-m-d')); sleep(3); return 0; }

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?

I've added a 3 second sleep in my php script and will observe.

Could you explain where to add the -vx switch?

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>: sieve: Thomas> msgid=62961d1c.5y4hr0Vqi97JFnyb%DABS.zsmsvp02@example.com: fileinto Thomas> action: stored mail into mailbox 'acme.DABS' Thomas> May 31 13:50:39 star dovecot[99425]: Thomas> lda(user)<99425>: sieve: Thomas> msgid=62961d1c.5y4hr0Vqi97JFnyb%DABS.zsmsvp02@example.com: stored mail Thomas> into mailbox 'INBOX' Thomas> May 31 13:50:39 star dovecot[99425]: Thomas> lda(user)<99425>: 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 = 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@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> }