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

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@flightsupport.ch writes:

Thomas> Hi John Thomas> 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?

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