[pmg-devel] [PATCH pmg-api v2] Add rule name to RuleAction logging

Stoiko Ivanov s.ivanov at proxmox.com
Thu Apr 18 17:04:32 CEST 2019


With complicated rulesets knowing which rule is responsible for the action
applied to a mail can become complex. Since relevant actions [0] do log a line
when being executed adding the rule's name to this logline should simplify
understanding and debugging complex rules.

Additionally the mix of string interpolation and formatstrings in Quarantine.pm
got unified to formatstrings.

[0] Attach is covered via Notify, Disclaimer and ModField could result in too
verbose logging (i.e. users adding many headers to a mail) without any gain

Signed-off-by: Stoiko Ivanov <s.ivanov at proxmox.com>
---

Thanks to Thomas for catching the syntax-error from my removing encode without
testing!

Changes v1 -> v2:
* fixed the misplaced ')'
* tested each testable logline for similar errors (only ReportSpam remains
untested, but it does not seem that this can be configured easily (i.e. without
manually inserting stuff into the DB) - I'd consider dropping the Action
(with a separate patch)


extra-info for v1:
Initially the patch did encode the RuleName as UTF-8, until I noticed that we
do not support that yet (interaction between Postgres and Perl - see #2057)
when creating a rule. Adding wider/complete support for UTF-8 for writing/
reading from the database should also probably happen while reading/writing
the Database (and is a fight for another day).

AFAIS the only caller of the execute subs of the Actions is bin/pmg-smtp-filter

My (quick) tests included sending a mail with that patch applied and checking
that the logs still show up in the Tracking Center.

 PMG/RuleDB/Accept.pm     |  6 ++++--
 PMG/RuleDB/BCC.pm        |  8 +++++---
 PMG/RuleDB/Block.pm      |  4 +++-
 PMG/RuleDB/Notify.pm     |  8 +++++---
 PMG/RuleDB/Quarantine.pm |  6 ++++--
 PMG/RuleDB/Remove.pm     | 10 ++++++----
 PMG/RuleDB/ReportSpam.pm |  3 +++
 7 files changed, 30 insertions(+), 15 deletions(-)

diff --git a/PMG/RuleDB/Accept.pm b/PMG/RuleDB/Accept.pm
index 2956927..1387e24 100644
--- a/PMG/RuleDB/Accept.pm
+++ b/PMG/RuleDB/Accept.pm
@@ -91,6 +91,8 @@ sub execute {
 
     my $subgroups = $mod_group->subgroups($targets, 1);
 
+    my $rulename = $vars->{RULE};
+
     foreach my $ta (@$subgroups) {
 	my ($tg, $entity) = (@$ta[0], @$ta[1]);
 
@@ -111,12 +113,12 @@ sub execute {
 		$msginfo->{xforward}, $msginfo->{fqdn});
 	    if ($qid) {
 		foreach (@$tg) {
-		    syslog('info', "%s: accept mail to <%s> (%s)", $queue->{logid}, encode('UTF-8', $_), $qid);
+		    syslog('info', "%s: accept mail to <%s> (rule: %s, %s)", $queue->{logid}, encode('UTF-8', $_), $rulename, $qid);
 		}
 		$queue->set_status ($tg, 'delivered', $qid);
 	    } else {
 		foreach (@$tg) {
-		    syslog('err', "%s: reinject mail to <%s> failed", $queue->{logid}, encode('UTF-8', $_));
+		    syslog('err', "%s: reinject mail to <%s> (rule: %s) failed", $queue->{logid}, encode('UTF-8', $_), $rulename);
 		}
 		if ($code) {
 		    my $resp = substr($code, 0, 1);
diff --git a/PMG/RuleDB/BCC.pm b/PMG/RuleDB/BCC.pm
index 1ee5561..cbe2810 100644
--- a/PMG/RuleDB/BCC.pm
+++ b/PMG/RuleDB/BCC.pm
@@ -114,12 +114,14 @@ sub execute {
 
     my $subgroups = $mod_group->subgroups($targets, 1);
 
+    my $rulename = $vars->{RULE};
+
     my $bcc_to = PMG::Utils::subst_values($self->{target}, $vars);
 
     if ($bcc_to =~ m/^\s*$/) {
 	# this happens if a notification is triggered by bounce mails
 	# which notifies the sender <> - we just log and then ignore it
-	syslog('info', "%s: bcc to <> (ignored)", $queue->{logid});
+	syslog('info', "%s: bcc to <> (rule: %s, ignored)", $queue->{logid}, $rulename);
 	return;
     }
 
@@ -148,9 +150,9 @@ sub execute {
 		$msginfo->{xforward}, $msginfo->{fqdn}, 1);
 	    foreach (@bcc_targets) {
 		if ($qid) {
-		    syslog('info', "%s: bcc to <%s> (%s)", $queue->{logid}, $_, $qid);
+		    syslog('info', "%s: bcc to <%s> (rule: %s, %s)", $queue->{logid}, $_, $rulename, $qid);
 		} else {
-		    syslog('err', "%s: bcc to <%s> failed", $queue->{logid}, $_);
+		    syslog('err', "%s: bcc to <%s> (rule: %s) failed", $queue->{logid}, $_, $rulename);
 		}
 	    }
 	}
diff --git a/PMG/RuleDB/Block.pm b/PMG/RuleDB/Block.pm
index 81f00b9..c7c640e 100644
--- a/PMG/RuleDB/Block.pm
+++ b/PMG/RuleDB/Block.pm
@@ -89,6 +89,8 @@ sub execute {
     my ($self, $queue, $ruledb, $mod_group, $targets, 
 	$msginfo, $vars, $marks) = @_;
 
+    my $rulename = $vars->{RULE};
+
     if ($msginfo->{testmode}) {
 	my $fh = $msginfo->{test_fh};
 	print $fh "block from: $msginfo->{sender}\n";
@@ -96,7 +98,7 @@ sub execute {
     }
 
     foreach my $to (@$targets) {
-	syslog('info', "%s: block mail to <%s>", $queue->{logid}, encode('UTF-8', $to));
+	syslog('info', "%s: block mail to <%s> (rule: %s)", $queue->{logid}, encode('UTF-8', $to), $rulename);
     }
 
     $queue->set_status($targets, 'blocked');
diff --git a/PMG/RuleDB/Notify.pm b/PMG/RuleDB/Notify.pm
index 22b8bd2..20d87af 100644
--- a/PMG/RuleDB/Notify.pm
+++ b/PMG/RuleDB/Notify.pm
@@ -207,6 +207,8 @@ sub execute {
 
     my $from = 'postmaster';
 
+    my $rulename = $vars->{RULE};
+
     my $body = PMG::Utils::subst_values($self->{body}, $vars);
     my $subject = PMG::Utils::subst_values($self->{subject}, $vars);
     my $to = PMG::Utils::subst_values($self->{to}, $vars);
@@ -214,7 +216,7 @@ sub execute {
     if ($to =~ m/^\s*$/) {
 	# this happens if a notification is triggered by bounce mails
 	# which notifies the sender <> - we just log and then ignore it
-	syslog('info', "%s: notify <> (ignored)", $queue->{logid});
+	syslog('info', "%s: notify <> (rule: %s, ignored)", $queue->{logid}, $rulename);
 	return;
     }
 
@@ -255,9 +257,9 @@ sub execute {
 	    $top, $from, \@targets, undef, $msginfo->{fqdn});
 	foreach (@targets) {
 	    if ($qid) {
-		syslog('info', "%s: notify <%s> (%s)", $queue->{logid}, $_, $qid);
+		syslog('info', "%s: notify <%s> (rule: %s, %s)", $queue->{logid}, $_, $rulename, $qid);
 	    } else {
-		syslog ('err', "%s: notify <%s> failed", $queue->{logid}, $_);
+		syslog ('err', "%s: notify <%s> (rule: %s) failed", $queue->{logid}, $_, $rulename);
 	    }
 	}
     }
diff --git a/PMG/RuleDB/Quarantine.pm b/PMG/RuleDB/Quarantine.pm
index eb423a7..487fa6e 100644
--- a/PMG/RuleDB/Quarantine.pm
+++ b/PMG/RuleDB/Quarantine.pm
@@ -89,6 +89,8 @@ sub execute {
     
     my $subgroups = $mod_group->subgroups($targets, 1);
 
+    my $rulename = $vars->{RULE};
+
     foreach my $ta (@$subgroups) {
 	my ($tg, $entity) = (@$ta[0], @$ta[1]);
 
@@ -98,7 +100,7 @@ sub execute {
 	    if (my $qid = $queue->quarantine_mail($ruledb, 'V', $entity, $tg, $msginfo, $vars, $ldap)) {
 
 		foreach (@$tg) {
-		    syslog ('info', "$queue->{logid}: moved mail for <%s> to virus quarantine - $qid", $_);
+		    syslog ('info', "$queue->{logid}: moved mail for <%s> to virus quarantine (rule: %s, %s)", $_, $rulename, $qid);
 		}
 
 		$queue->set_status ($tg, 'delivered');
@@ -108,7 +110,7 @@ sub execute {
 	    if (my $qid = $queue->quarantine_mail($ruledb, 'S', $entity, $tg, $msginfo, $vars, $ldap)) {
 
 		foreach (@$tg) {
-		    syslog ('info', "$queue->{logid}: moved mail for <%s> to spam quarantine - $qid", $_);
+		    syslog ('info', "$queue->{logid}: moved mail for <%s> to spam quarantine (rule: %s, %s)", $_, $rulename, $qid);
 		}
 
 		$queue->set_status($tg, 'delivered');
diff --git a/PMG/RuleDB/Remove.pm b/PMG/RuleDB/Remove.pm
index 1bb7a85..551fb97 100644
--- a/PMG/RuleDB/Remove.pm
+++ b/PMG/RuleDB/Remove.pm
@@ -111,7 +111,7 @@ sub save {
 }
 
 sub delete_marked_parts {
-    my ($self, $queue, $entity, $html, $rtype, $marks) = @_;
+    my ($self, $queue, $entity, $html, $rtype, $marks, $rulename) = @_;
 
     my $nparts = [];
 
@@ -155,8 +155,8 @@ sub delete_marked_parts {
 
 	    push (@$nparts, $ent);
 
-	    syslog ('info', "%s: removed attachment $id ('%s')",
-		    $queue->{logid}, $on);
+	    syslog ('info', "%s: removed attachment $id ('%s', rule: %s)",
+		    $queue->{logid}, $on, $rulename);
 
 	} else {
 	    $self->delete_marked_parts($queue, $part, $html, $rtype, $marks);
@@ -171,6 +171,8 @@ sub execute {
     my ($self, $queue, $ruledb, $mod_group, $targets,
 	$msginfo, $vars, $marks) = @_;
 
+    my $rulename = $vars->{RULE};
+
     if (!$self->{all} && ($#$marks == -1)) {
 	# no marks
 	return;
@@ -200,7 +202,7 @@ sub execute {
 	    $entity->head->delete('x-proxmox-tmp-aid');
 	}
 
-	$self->delete_marked_parts($queue, $entity, $html, $rtype, $marks);
+	$self->delete_marked_parts($queue, $entity, $html, $rtype, $marks, $rulename);
 
 	if ($msginfo->{testmode}) {
 	    $entity->head->mime_attr('Content-type.boundary' => '------=_TEST123456') if $entity->is_multipart;
diff --git a/PMG/RuleDB/ReportSpam.pm b/PMG/RuleDB/ReportSpam.pm
index 105a67f..a3e06ee 100644
--- a/PMG/RuleDB/ReportSpam.pm
+++ b/PMG/RuleDB/ReportSpam.pm
@@ -85,6 +85,8 @@ sub execute {
     my ($self, $queue, $ruledb, $mod_group, $targets, 
 	$msginfo, $vars, $marks) = @_;
 
+    my $rulename = $vars->{RULE};
+
     my $subgroups = $mod_group->subgroups($targets);
 
     foreach my $ta (@$subgroups) {
@@ -105,6 +107,7 @@ sub execute {
 	    
 	    $mail->finish();	
 	}
+	syslog('info', "%s: report mail as spam (rule: %s)", $queue->{logid}, $rulename);
 	$queue->set_status ($tg, 'delivered');
     }
 }
-- 
2.11.0




More information about the pmg-devel mailing list