Random behavior with sieve extprograms
Thomas Sommer
ts-2016 at flightsupport.ch
Wed Jun 1 07:57:55 UTC 2022
Hi John
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?
"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><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> }
More information about the dovecot
mailing list