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 exceptionsin that script and making sure you only return errors when therereally is an error?
Thomas> Emails matching the condition are processed by a laravel (php)artisanThomas> 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'smultiple places things could go wrong. Why not just pipe directly tothe php script (which wasn't included unless I'm totally blind anddumb tonight... :-) instead?
"sieve-dabs-execute.sh" is just the socket name. It was a shell scriptpreviously and I never updated the socket name. See servicesieve-pipe-script in the dovecot -n output.It calls the php script directly:executable = script /usr/bin/php /srv/www/mydomain/status/artisandabs: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 sleepinto your shell script at the end would be good? Or maybe run withthe -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 alwaysprocessedThomas> 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 asThomas> below.
Thomas> May 31 13:50:38 star dovecot[99425]:Thomas> lda(user)<99425>
: sieve:Thomas> msgid=62961d1c.5y4hr0Vqi97JFnyb%DABS.zsmsvp02@example.com:fileintoThomas> 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 mailThomas> into mailbox 'INBOX'Thomas> May 31 13:50:39 star dovecot[99425]:Thomas> lda(user)<99425> : sieve: Execution ofscriptThomas> /home/user/sieve/.dovecot.sieve failed, but implicit keep wassuccessfulThomas> (user logfile /home/user/sieve/.dovecot.sieve.log may revealadditionalThomas> 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': referThomas> to server log for more information. [2022-05-31 13:50:39].
Thomas> It's weird. "failed to pipe message to program" is simply nottrue. TheThomas> command was processed correctly.
Thomas> Any ideas where to look for clues or how to debug this?
Thomas> RegardsThomas> Thomas
Thomas> config:
Thomas> # 2.3.14 (cee3cbc0d): /etc/dovecot/dovecot.confThomas> # Pigeonhole version 0.5.14 (1b5c82b2)Thomas> # OS: Linux 5.17.5-x86_64-linode154 x86_64 Ubuntu 20.04.4 LTSThomas> auth_mechanisms = plain loginThomas> auth_username_format = %nThomas> auth_verbose = yesThomas> mail_location = maildir:~/MaildirThomas> mail_plugins = " quota"Thomas> managesieve_notify_capability = mailtoThomas> managesieve_sieve_capability = fileinto reject envelopeThomas> encoded-character vacation subaddresscomparator-i;ascii-numericThomas> relational regex imap4flags copy include variables body enotifyThomas> environment mailbox date index ihave duplicate mimeforeverypartThomas> extracttext vnd.dovecot.pipe vnd.dovecot.executeThomas> namespace inbox {Thomas> inbox = yesThomas> location =Thomas> mailbox Drafts {Thomas> special_use = \DraftsThomas> }Thomas> mailbox Junk {Thomas> special_use = \JunkThomas> }Thomas> mailbox Sent {Thomas> special_use = \SentThomas> }Thomas> mailbox "Sent Messages" {Thomas> special_use = \SentThomas> }Thomas> mailbox Trash {Thomas> special_use = \TrashThomas> }Thomas> prefix =Thomas> }Thomas> passdb {Thomas> driver = pamThomas> }Thomas> plugin {Thomas> quota = fs:User quotaThomas> quota_grace = 1%%Thomas> quota_status_nouser = DUNNOThomas> quota_status_overquota = 552 5.2.2 Mailbox is fullThomas> quota_status_success = DUNNOThomas> sieve = file:~/sieve;active=~/sieve/.dovecot.sieveThomas> sieve_execute_socket_dir =Thomas> sieve_extensions = +vnd.dovecot.pipe +vnd.dovecot.executeThomas> sieve_pipe_exec_timeout = 30sThomas> sieve_pipe_socket_dir =Thomas> sieve_plugins = sieve_extprogramsThomas> sieve_redirect_envelope_from = recipientThomas> sieve_trace_debug = noThomas> sieve_trace_dir = ~/sieve/traceThomas> sieve_trace_level = matchingThomas> }Thomas> protocols = imap sieveThomas> service auth {Thomas> unix_listener /var/spool/postfix/private/dovecot-auth {Thomas> group = postfixThomas> mode = 0660Thomas> user = postfixThomas> }Thomas> }Thomas> service quota-status {Thomas> client_limit = 1Thomas> executable = /usr/lib/dovecot/quota-status -p postfixThomas> inet_listener {Thomas> address = 127.0.0.1Thomas> port = 8881Thomas> }Thomas> }Thomas> service sieve-pipe-script {Thomas> executable = script /usr/bin/php/srv/www/mydomain/status/artisanThomas> dabs:processEmailThomas> unix_listener sieve-dabs-execute.sh {Thomas> mode = 0660Thomas> user = userThomas> }Thomas> user = www-dataThomas> vsz_limit = 512 MThomas> }Thomas> ssl = requiredThomas> ssl_cert = ssl_cipher_list = AES128+EECDH:AES128+EDHThomas> ssl_client_ca_dir = /etc/ssl/certsThomas> ssl_dh = # hidden, use -P to show itThomas> ssl_key = # hidden, use -P to show itThomas> ssl_min_protocol = TLSv1.2Thomas> ssl_prefer_server_ciphers = yesThomas> userdb {Thomas> driver = passwdThomas> }Thomas> protocol lda {Thomas> deliver_log_format = msgid=%m: %$Thomas> mail_plugins = " quota sieve"Thomas> postmaster_address = postmaster@mydomain.chThomas> quota_full_tempfail = yesThomas> rejection_reason = Your message to <%t> was automaticallyThomas> rejected:%n%rThomas> }Thomas> protocol imap {Thomas> mail_max_userip_connections = 20Thomas> mail_plugins = " quota mail_log notify imap_quota"Thomas> }
