[pmg-devel] [PATCH pmg-api/docs] make filter timeout configurable

[pmg-devel] [PATCH pmg-api/docs] make filter timeout configurable

[Stoiko Ivanov]

This series improves mail-handling in case pmg-smtp-filter takes too long in
processing a mail.
Currently the timeout is based on postfix defaults which differ between
after-queue filtering (600s) and before-queue filtering (120s) (patch 1/4
unifies the timeout, and is meant as a stop-gap measure).

In both cases - once the timeout is reached the behavior is inconvenient
(to put it mildly):
* postfix detects the timeout and reports a temporary 4xx code to the
  sender, while pmg-smtp-filter sends the mail further after processing
  anyways
This results in such mails getting delivered multiple times to the
recipient (and you need the administrator of the server sending to PMG to
remove it from their queue, for the deliveries to stop).

Tested by adding a `sleep 200;` in PMG::Utils::analyze_virus_clam.

The docs patch is necessary for patch 3/5 (new config-options need to be
known in the doc-generator)

pmg-api:
Stoiko Ivanov (4):
  templates: postfix: set same timeouts for before and after-queue
  pmg-smtp-filter: refactor use of gettimeofday
  config: postfix: make smtp-filter-timeout configurable
  pmg-smtp-filter: die if processing took longer than the timeout

 src/PMG/Config.pm        |  6 ++++++
 src/bin/pmg-smtp-filter  | 22 +++++++++++++---------
 src/templates/main.cf.in |  5 ++++-
 3 files changed, 23 insertions(+), 10 deletions(-)

pmg-docs:
Stoiko Ivanov (1):
  doc-generator: add new option filter_timeout

 gen-pmg.conf.5-opts.pl | 1 +
 1 file changed, 1 insertion(+)

-- 
2.39.2

[pmg-devel] [PATCH pmg-api 1/4] templates: postfix: set same timeouts for before and after-queue

[Stoiko Ivanov]

When a mail takes longer to get processed (observed with some scanned
pages as pdf - where clamav+avast took 2.2 minutes for scanning) the
behavior of the filtering is different between before-queue and
after-queue filtering:
In the before-queue case the timeout is `$smtpd_proxy_timout` (120s)
[0], so the mail does not get processed in time and the listening
smtpd responds with `451 4.3.0 Error: queue file write error`. However
pmg-smtp-filter sends the mail to the smtpd on 10025 once it's done.
the original sender resends the mail due to the 451 error - which
results in the mail getting delivered multiple times (until it gets
removed from the queue on the original sender)

In the after-queue case the timeout is `$lmtp_data_done_timeout`
(pmg-smtp-filter acts as lmtp server) (600s) - so the mail gets
send successfully only once. In case the processing time reaches
600s the behavior is equivalent - but for lmtp postfix logs:
```
...timed out while sending end of data -- message may be sent more
than once
```

The value needs to be set as literal - referring to the builtin
default as `$lmtp_data_done_timeout` does not work.

While the underlying issue of mails getting send multiple times in
case the timeout is reached is not fixed by this - having the same
timeout in both cases is a good idea and 600s increases the chances
of clamav+avast+custom_check_script+spamassassin to get their job done.

tested by adding a `sleep 200` in PMG::Utils::analyze_virus_clam.
(before the eval block running with the 5 minute timeout)

[0] https://www.postfix.org/SMTPD_PROXY_README.html#parameters

Reported-by: Martin Maurer <martin@proxmox.com>
Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 src/templates/main.cf.in | 4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

diff --git a/src/templates/main.cf.in b/src/templates/main.cf.in
index bce0353..516bc2f 100644
--- a/src/templates/main.cf.in
+++ b/src/templates/main.cf.in
@@ -49,7 +49,9 @@ relay_transport = [% pmg.mail.relayprotocol %]:[% pmg.mail.relay %]:[% pmg.mail.
 default_transport = smtp:[% pmg.mail.smarthost %]:[% pmg.mail.smarthostport %]
 [% END %]
 
-[% IF ! pmg.mail.before_queue_filtering -%]
+[% IF pmg.mail.before_queue_filtering -%]
+smtpd_proxy_timeout = 600s
+[% ELSE %]
 content_filter=scan:127.0.0.1:10024
 [%- END %]
 
-- 
2.39.2

[pmg-devel] [PATCH pmg-api 2/4] pmg-smtp-filter: refactor use of gettimeofday

[Stoiko Ivanov]

in preparation for handling a processing timeout and passing the
startime to apply_rules, just unify the different syntax we use
throught the file.

no semantic change intended.

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 src/bin/pmg-smtp-filter | 15 ++++++---------
 1 file changed, 6 insertions(+), 9 deletions(-)

diff --git a/src/bin/pmg-smtp-filter b/src/bin/pmg-smtp-filter
index 13da635..011dd16 100755
--- a/src/bin/pmg-smtp-filter
+++ b/src/bin/pmg-smtp-filter
@@ -524,7 +524,7 @@ sub run_dequeue {
 
     $self->log (2, "starting database maintenance");
 
-    my ($csec, $usec) = gettimeofday ();
+    my $starttime = [ gettimeofday() ];
 
     my $cinfo = PVE::INotify::read_file("cluster.conf");
 
@@ -540,8 +540,7 @@ sub run_dequeue {
     if ($err) {
 	$self->log (0, $err);
     } else {
-	my ($csec_end, $usec_end) = gettimeofday ();
-	my $ptime = int (($csec_end - $csec) * 1000 + ($usec_end - $usec) / 1000);
+	my $ptime = int(tv_interval($starttime) * 1000);
 	$self->log (2, "end database maintenance ($ptime ms)");
     }
 
@@ -560,7 +559,7 @@ sub unpack_entity {
 	if (PMG::Unpack::is_archive ($magic)) {
 	    $self->log (3, "$queue->{logid}: found archive '$filename' ($magic)");
 
-	    my $start = [gettimeofday];
+	    my $start = [ gettimeofday() ];
 
 	    $unpack->{mime} = {};
 
@@ -591,7 +590,7 @@ sub unpack_entity {
 sub handle_smtp {
     my ($self, $smtp) = @_;
 
-    my ($csec, $usec) = gettimeofday ();
+    my $starttime = [ gettimeofday() ];
 
     my $queue;
     my $msginfo = {};
@@ -714,7 +713,7 @@ sub handle_smtp {
 	    my $decdir = $queue->{dumpdir} . "/__decoded_archives";
 	    mkdir $decdir;
 
-	    my $start = [gettimeofday];
+	    my $start = [ gettimeofday() ];
 
 	    my $unpack;
 	    eval {
@@ -769,9 +768,7 @@ sub handle_smtp {
 
     die $err if $err;
 
-    my ($csec_end, $usec_end) = gettimeofday ();
-    my $time_total =
-	int (($csec_end-$csec)*1000 + ($usec_end - $usec)/1000);
+    my $time_total = int(tv_interval($starttime) * 1000);
 
 # PHASE 5 - log statistics
 # on error: log error messages
-- 
2.39.2

[pmg-devel] [PATCH pmg-api 3/4] config: postfix: make smtp-filter-timeout configurable

[Stoiko Ivanov]

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
This patch needs the changes for pmg-docs (actually an updated
pmg-doc-generator package installed) applied.

 src/PMG/Config.pm        | 6 ++++++
 src/templates/main.cf.in | 3 ++-
 2 files changed, 8 insertions(+), 1 deletion(-)

diff --git a/src/PMG/Config.pm b/src/PMG/Config.pm
index 7339e0d..eb6c5c2 100644
--- a/src/PMG/Config.pm
+++ b/src/PMG/Config.pm
@@ -699,6 +699,11 @@ sub properties {
 	    type => 'boolean',
 	    default => 1
 	},
+	filter_timeout => {
+	    description => "Timeout for the processing of one mail (in seconds)  (postfix option `smtpd_proxy_timeout` and `lmtp_data_done_timeout`)",
+	    type => 'integer',
+	    default => 600
+	},
     };
 }
 
@@ -740,6 +745,7 @@ sub options {
 	before_queue_filtering => { optional => 1 },
 	ndr_on_block => { optional => 1 },
 	smtputf8 => { optional => 1 },
+	filter_timeout => { optional => 1 },
     };
 }
 
diff --git a/src/templates/main.cf.in b/src/templates/main.cf.in
index 516bc2f..764f9a3 100644
--- a/src/templates/main.cf.in
+++ b/src/templates/main.cf.in
@@ -50,9 +50,10 @@ default_transport = smtp:[% pmg.mail.smarthost %]:[% pmg.mail.smarthostport %]
 [% END %]
 
 [% IF pmg.mail.before_queue_filtering -%]
-smtpd_proxy_timeout = 600s
+smtpd_proxy_timeout = [% pmg.mail.filter_timeout %]s
 [% ELSE %]
 content_filter=scan:127.0.0.1:10024
+lmtp_data_done_timeout = [% pmg.mail.filter_timeout %]s
 [%- END %]
 
 mail_name = Proxmox
-- 
2.39.2

[pmg-devel] [PATCH pmg-api 4/4] pmg-smtp-filter: die if processing took longer than the timeout

[Stoiko Ivanov]

In case a mail took longer to get processed than the configured
timeout - 1 second - `die` before running any action.

The `die` results in a temporary failure to be reported to the sending
server by PMG::SMTP.pm ("451 4.4.0 detected undelivered mail").

The reason for the 1s extra slack is to have some time to actually
run the action - and also justified that in both cases (postfix
detecting the timeout, and pmg-smtp-filter `die`ing the sender gets
a temporary failure reported back).

Tested with a small filter_timeout setting (30), and a larger sleep in
analyze_virus added in analyze virus.

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 src/bin/pmg-smtp-filter | 7 +++++++
 1 file changed, 7 insertions(+)

diff --git a/src/bin/pmg-smtp-filter b/src/bin/pmg-smtp-filter
index 011dd16..1c2c816 100755
--- a/src/bin/pmg-smtp-filter
+++ b/src/bin/pmg-smtp-filter
@@ -316,6 +316,12 @@ sub apply_rules {
 
     my $mod_group = PMG::ModGroup->new($entity, $msginfo->{targets});
 
+    my $processing_time = int(tv_interval($msginfo->{starttime}));
+    my $filter_timeout = $self->{pmg_cfg}->get('mail', 'filter_timeout');
+    if ( ($processing_time - 1) >= $filter_timeout) {
+	die "processing took $processing_time s, longer than the timeout ($filter_timeout)\n";
+    }
+
     foreach my $rule (@$rules) {
 	my $targets = $rule_targets{$rule->{id}};
 	next if !$targets;
@@ -637,6 +643,7 @@ sub handle_smtp {
 	$msginfo->{fqdn} = $msginfo->{hostname};
 	$msginfo->{fqdn} .= ".$msginfo->{domain}" if $msginfo->{domain};
 	$msginfo->{lcid} = $lcid;
+	$msginfo->{starttime} = $starttime;
 
 	# $msginfo->{targets} is case sensitive,
 	# but pmail is always lower case!
-- 
2.39.2

[pmg-devel] [PATCH pmg-docs 1/1] doc-generator: add new option filter_timeout

[Stoiko Ivanov]

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 gen-pmg.conf.5-opts.pl | 1 +
 1 file changed, 1 insertion(+)

diff --git a/gen-pmg.conf.5-opts.pl b/gen-pmg.conf.5-opts.pl
index 1aff46a..85951af 100755
--- a/gen-pmg.conf.5-opts.pl
+++ b/gen-pmg.conf.5-opts.pl
@@ -43,6 +43,7 @@ my $key_groups = {
 	    before_queue_filtering => 1,
 	    ndr_on_block => 1,
 	    smtputf8 => 1,
+	    filter_timeout => 1,
 	}],
     'mail-tls' => [
 	'mail' , {
-- 
2.39.2

Re: [pmg-devel] [PATCH pmg-api/docs] make filter timeout configurable

[Dominik Csapak]

gave this a look & spin, and it works as intended

writing here what we discussed off-list:

there is still the same race when processing + the actual action
takes longer than the time out, but that is no trivially fixable

for "normal" timeouts (e.g. the default of 600s) this should not
matter much, except for pathological cases where e.g. writing
to the quarantine takes an absurd amount of time

secondly, we probably should adapt the timeouts for virus+custom check scripts
to the configured one too (or e.g. half) but that can be done afterwards
and does not impact the actual issue here
(except that probably the command runs unnecessarily long)

IMHO we should still mark the increased timeout for before queue filter
in the next release notes, since that can be a bit unexpected

so from my side, this series is:

Reviewed-by: Dominik Csapak <d.csapak@proxmox.com>
Tested-by: Dominik Csapak <d.csapak@proxmox.com>

Re: [pmg-devel] [PATCH pmg-api 3/4] config: postfix: make smtp-filter-timeout configurable

[Thomas Lamprecht]

Am 11/09/2023 um 16:23 schrieb Stoiko Ivanov:
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
> This patch needs the changes for pmg-docs (actually an updated
> pmg-doc-generator package installed) applied.
> 
>  src/PMG/Config.pm        | 6 ++++++
>  src/templates/main.cf.in | 3 ++-
>  2 files changed, 8 insertions(+), 1 deletion(-)
> 
> diff --git a/src/PMG/Config.pm b/src/PMG/Config.pm
> index 7339e0d..eb6c5c2 100644
> --- a/src/PMG/Config.pm
> +++ b/src/PMG/Config.pm
> @@ -699,6 +699,11 @@ sub properties {
>  	    type => 'boolean',
>  	    default => 1
>  	},
> +	filter_timeout => {

Style nit: snake_case, but without checking there's probably a lot of
those casing already present? if not, or already a mix, I'd also prefer
using kebab-case here for new stuff.

> +	    description => "Timeout for the processing of one mail (in seconds)  (postfix option `smtpd_proxy_timeout` and `lmtp_data_done_timeout`)",

Can you wrap that please over multiple lines so that our << 100 cc style
rule is held up, e.g.:

            description => "Timeout for the processing of one mail (in seconds)  (postfix option"
                ." `smtpd_proxy_timeout` and `lmtp_data_done_timeout`)",

> +	    type => 'integer',
> +	    default => 600

min/max would be great to have here, makes no sense to have -10 or? and
limiting the upper site to is often helpful too, having a timeout more
than a day (86400) or week (604800) is probably a high enough limit to
catch some odd mistaken entries.

> +	},
>      };
>  }
>  

Re: [pmg-devel] [PATCH pmg-api 4/4] pmg-smtp-filter: die if processing took longer than the timeout

[Thomas Lamprecht]

Am 11/09/2023 um 16:23 schrieb Stoiko Ivanov:
> In case a mail took longer to get processed than the configured
> timeout - 1 second - `die` before running any action.
> 
> The `die` results in a temporary failure to be reported to the sending
> server by PMG::SMTP.pm ("451 4.4.0 detected undelivered mail").
> 
> The reason for the 1s extra slack is to have some time to actually
> run the action - and also justified that in both cases (postfix
> detecting the timeout, and pmg-smtp-filter `die`ing the sender gets
> a temporary failure reported back).
> 
> Tested with a small filter_timeout setting (30), and a larger sleep in
> analyze_virus added in analyze virus.
> 
> Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
> ---
>  src/bin/pmg-smtp-filter | 7 +++++++
>  1 file changed, 7 insertions(+)
> 
> diff --git a/src/bin/pmg-smtp-filter b/src/bin/pmg-smtp-filter
> index 011dd16..1c2c816 100755
> --- a/src/bin/pmg-smtp-filter
> +++ b/src/bin/pmg-smtp-filter
> @@ -316,6 +316,12 @@ sub apply_rules {
>  
>      my $mod_group = PMG::ModGroup->new($entity, $msginfo->{targets});
>  
> +    my $processing_time = int(tv_interval($msginfo->{starttime}));
> +    my $filter_timeout = $self->{pmg_cfg}->get('mail', 'filter_timeout');
> +    if ( ($processing_time - 1) >= $filter_timeout) {

style nit: extra whitespace after the opening parenthesis of the if expression
and the first parenthesis of the actual expression, here you actually would not
need any parenthesis at all, i.e., either like now:

 if ($processing_time - 1 >= $filter_timeout) {

or by optimizing the substraction away by switching to greater-than:

 if ($processing_time > $filter_timeout) {

or a post-if:

die "processing took $processing_time s, longer than the timeout ($filter_timeout)\n"
    if $processing_time > $filter_timeout;


Which I would prefer for that quite simple check, but no hard feelings.

> +	die "processing took $processing_time s, longer than the timeout ($filter_timeout)\n";
> +    }
> +
>      foreach my $rule (@$rules) {
>  	my $targets = $rule_targets{$rule->{id}};
>  	next if !$targets;

Re: [pmg-devel] [PATCH pmg-api/docs] make filter timeout configurable

[Stoiko Ivanov]

Thank you very much for the review, testing and the discussion!

Just summing up some points from the talks:

On Fri, 12 Jan 2024 09:35:09 +0100
Dominik Csapak <d.csapak@proxmox.com> wrote:

> gave this a look & spin, and it works as intended
> 
> writing here what we discussed off-list:
> 
> there is still the same race when processing + the actual action
> takes longer than the time out, but that is no trivially fixable
One option to handle this would be to 'dry-run' the (final) actions
for each target-group, assuming that they work, i.e.:
that the mail is considered 'delivered' for accept and quarantine, and
'blocked' for block. with that information pmg-smtp-filter could
answer to the sending postfix, and then start processing the actions.
It would only need to generate a bounce if an accepted mail is not
successfully sent to the postfix on 10025.

But this entails refactoring PMG::SMTP and pmg-smtp-filter -
pmg-smtp-filter would need to return after processing who,what,when
and then SMTP would need to call a second function which deals with
running the actions, writing statistics, ...)
> 
> for "normal" timeouts (e.g. the default of 600s) this should not
> matter much, except for pathological cases where e.g. writing
> to the quarantine takes an absurd amount of time

In case a quarantine insert takes so long (and the processing of a mail
took 599s before) - the issue of getting a mail multiple times is probably
not your largest problem.

> 
> secondly, we probably should adapt the timeouts for virus+custom check scripts
> to the configured one too (or e.g. half) but that can be done afterwards
Thinking about it - I think min($filter_timeout, 5*60) (5 minutes is the
current timeout for virus+custom-checks, might make for a robust change.
splitting the timeout seems odd (just because clamAV needs more than
half the timeout, does not mean that custom checks + avast (if configured
at all) or spamassassin won't finish in a very short time.

as an alternative (which I'd only consider if someone actually runs into
such an issue) - we might introduce timeouts for each of the potentially
long-running things.


> and does not impact the actual issue here
> (except that probably the command runs unnecessarily long)
> 
> IMHO we should still mark the increased timeout for before queue filter
> in the next release notes, since that can be a bit unexpected
Good point - definitely worth mentioning

> 
> so from my side, this series is:
> 
> Reviewed-by: Dominik Csapak <d.csapak@proxmox.com>
> Tested-by: Dominik Csapak <d.csapak@proxmox.com>
>