Re: Random behavior with sieve extprograms
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 writes:
Thomas> Hi John
Thomas> On 2022-06-01 02:50, John Stoffel wrote:
"Thomas" == Thomas Sommer 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" "d...@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,
Re: Random behavior with sieve extprograms
Hi John
On 2022-06-01 02:50, John Stoffel wrote:
"Thomas" == Thomas Sommer 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" "d...@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.zsmsv...@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.zsmsv...@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
Random behavior with sieve extprograms
Hi
I have a random behavior with dovecot and sieve extprograms.
Here is my sieve file:
require ["fileinto", "vnd.dovecot.pipe", "copy", "imap4flags"];
# rule:[DABS]
if header :contains "X-Original-To" "d...@mydomain.ch"
{
pipe "sieve-dabs-execute.sh";
setflag "\\Seen";
fileinto "acme.DABS";
stop;
}
Emails matching the condition are processed by a laravel (php) artisan
command. See service sieve-pipe-script below.
The exit code of this php command is 0.
I randomly get the following in my postfix logs:
Sieve thinks that the command failed, but the email was always processed
correctly. In that case I get a copy in my Inbox.
I'm wondering what could be the cause for this random behavior.
My guess is that approximately 70% are processed correctly, 30% is as
below.
May 31 13:50:38 star dovecot[99425]:
lda(user)<99425>: sieve:
msgid=<62961d1c.5y4hr0vqi97jfnyb%dabs.zsmsv...@example.com>: fileinto
action: stored mail into mailbox 'acme.DABS'
May 31 13:50:39 star dovecot[99425]:
lda(user)<99425>: sieve:
msgid=<62961d1c.5y4hr0vqi97jfnyb%dabs.zsmsv...@example.com>: stored mail
into mailbox 'INBOX'
May 31 13:50:39 star dovecot[99425]:
lda(user)<99425>: sieve: Execution of script
/home/user/sieve/.dovecot.sieve failed, but implicit keep was successful
(user logfile /home/user/sieve/.dovecot.sieve.log may reveal additional
details)
.dovecot.sieve.log:
sieve: info: started log at May 31 13:50:39.
error: failed to pipe message to program `sieve-dabs-execute.sh': refer
to server log for more information. [2022-05-31 13:50:39].
It's weird. "failed to pipe message to program" is simply not true. The
command was processed correctly.
Any ideas where to look for clues or how to debug this?
Regards
Thomas
config:
# 2.3.14 (cee3cbc0d): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.14 (1b5c82b2)
# OS: Linux 5.17.5-x86_64-linode154 x86_64 Ubuntu 20.04.4 LTS
auth_mechanisms = plain login
auth_username_format = %n
auth_verbose = yes
mail_location = maildir:~/Maildir
mail_plugins = " quota"
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope
encoded-character vacation subaddress comparator-i;ascii-numeric
relational regex imap4flags copy include variables body enotify
environment mailbox date index ihave duplicate mime foreverypart
extracttext vnd.dovecot.pipe vnd.dovecot.execute
namespace inbox {
inbox = yes
location =
mailbox Drafts {
special_use = \Drafts
}
mailbox Junk {
special_use = \Junk
}
mailbox Sent {
special_use = \Sent
}
mailbox "Sent Messages" {
special_use = \Sent
}
mailbox Trash {
special_use = \Trash
}
prefix =
}
passdb {
driver = pam
}
plugin {
quota = fs:User quota
quota_grace = 1%%
quota_status_nouser = DUNNO
quota_status_overquota = 552 5.2.2 Mailbox is full
quota_status_success = DUNNO
sieve = file:~/sieve;active=~/sieve/.dovecot.sieve
sieve_execute_socket_dir =
sieve_extensions = +vnd.dovecot.pipe +vnd.dovecot.execute
sieve_pipe_exec_timeout = 30s
sieve_pipe_socket_dir =
sieve_plugins = sieve_extprograms
sieve_redirect_envelope_from = recipient
sieve_trace_debug = no
sieve_trace_dir = ~/sieve/trace
sieve_trace_level = matching
}
protocols = imap sieve
service auth {
unix_listener /var/spool/postfix/private/dovecot-auth {
group = postfix
mode = 0660
user = postfix
}
}
service quota-status {
client_limit = 1
executable = /usr/lib/dovecot/quota-status -p postfix
inet_listener {
address = 127.0.0.1
port = 8881
}
}
service sieve-pipe-script {
executable = script /usr/bin/php /srv/www/mydomain/status/artisan
dabs:processEmail
unix_listener sieve-dabs-execute.sh {
mode = 0660
user = user
}
user = www-data
vsz_limit = 512 M
}
ssl = required
ssl_cert = rejection_reason = Your message to <%t> was automatically
rejected:%n%r
}
protocol imap {
mail_max_userip_connections = 20
mail_plugins = " quota mail_log notify imap_quota"
}
