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

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

[Stoiko Ivanov]

v1->v2:
* addressed Thomas' feedback - Thanks very much
* changed the setting from filter_timeout to filter-timeout (thus
  template toolkit needs to access it as 'pmg.mail.item('filter-timeout')
* fixed a few glitches in the commit messages

original cover-letter for v1:
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: cleanup 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        |  9 +++++++++
 src/bin/pmg-smtp-filter  | 21 ++++++++++++---------
 src/templates/main.cf.in |  5 ++++-
 3 files changed, 25 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-docs v2 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..72ee379 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

[pmg-devel] [PATCH pmg-api v2 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 sent 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 3b56355..51cdd8b 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 v2 2/4] pmg-smtp-filter: cleanup 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 7da3de8..ba4e58e 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 v2 3/4] config: postfix: make smtp-filter-timeout configurable

[Stoiko Ivanov]

accessing the value in the config-template needs to use the
item virtual method (`pmg.mail.item('filter-timeout')` instead of the
. operator, due to using kebab-case for 'filter-timeout' see [0].

the minimal value is set to 2 as we add 1 second for the rules
processing in the next patch, and postfix has 1 as minimum.

[0] http://template-toolkit.org/docs/manual/VMethods.html#section_item

Signed-off-by: Stoiko Ivanov <s.ivanov@proxmox.com>
---
 src/PMG/Config.pm        | 9 +++++++++
 src/templates/main.cf.in | 3 ++-
 2 files changed, 11 insertions(+), 1 deletion(-)

diff --git a/src/PMG/Config.pm b/src/PMG/Config.pm
index 7339e0d..43baec5 100644
--- a/src/PMG/Config.pm
+++ b/src/PMG/Config.pm
@@ -699,6 +699,14 @@ 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,
+	    minimum => 2,
+	    maximum => 86400
+	},
     };
 }
 
@@ -740,6 +748,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 51cdd8b..434d5cd 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.item('filter-timeout') %]s
 [% ELSE %]
 content_filter=scan:127.0.0.1:10024
+lmtp_data_done_timeout = [% pmg.mail.item('filter-timeout') %]s
 [%- END %]
 
 mail_name = Proxmox
-- 
2.39.2

[pmg-devel] [PATCH pmg-api v2 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
added in analyze_virus.

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

diff --git a/src/bin/pmg-smtp-filter b/src/bin/pmg-smtp-filter
index ba4e58e..79d951c 100755
--- a/src/bin/pmg-smtp-filter
+++ b/src/bin/pmg-smtp-filter
@@ -316,6 +316,11 @@ 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');
+    die "processing took ${processing_time}s, longer than the timeout (${filter_timeout}s)\n"
+	if $processing_time > $filter_timeout;
+
     foreach my $rule (@$rules) {
 	my $targets = $rule_targets{$rule->{id}};
 	next if !$targets;
@@ -637,6 +642,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

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

[Dominik Csapak]

Looked and tested this, and it does what it says on the tin.

My original concern still exists but that would require a much more
intrusive fix (that we can still do in the future):

when the sending/remaining processing of the mail (aka the actions)
take longer than what time we still have remaining, we have
the same behavior as the original problem.

a short example:

filter-timeout: x seconds
processing up to the check: y seconds (but smaller than x)

if now the actions take more than 'x - y' seconds, the first
postfix instance runs into it's timeout, but the pmg-smtp-filter
is already processing the action (e.g. sending/quarantining)

To completely fix that, we'd have to (before the timeout check):
find out what actions would be taken,
return the postfix that status as if it was done
(e.g. accept/reject) (if that's even possible?)

and then do the actual action.
if that fails, we'd have to take an appropriate action,
e.g. send an ndr.

Aside from that, consider this series

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

[pmg-devel] applied-series: [PATCH pmg-api/pmg-docs v2] make filter timeout configurable

[Thomas Lamprecht]

Am 12/01/2024 um 20:21 schrieb Stoiko Ivanov:
> v1->v2:
> * addressed Thomas' feedback - Thanks very much
> * changed the setting from filter_timeout to filter-timeout (thus
>   template toolkit needs to access it as 'pmg.mail.item('filter-timeout')
> * fixed a few glitches in the commit messages
> 
> original cover-letter for v1:
> 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: cleanup 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        |  9 +++++++++
>  src/bin/pmg-smtp-filter  | 21 ++++++++++++---------
>  src/templates/main.cf.in |  5 ++++-
>  3 files changed, 25 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(+)
> 


applied, with Dominik's R-b & T-b, thanks!