diff --git a/scripts/innreport-display.conf b/scripts/innreport-display.conf index a7dbddc..191e0aa 100644 --- a/scripts/innreport-display.conf +++ b/scripts/innreport-display.conf @@ -965,6 +965,154 @@ section cleanfeed_ng_events { }; }; +# Postfilter-NG final article outcomes. Unlike the optional detailed rule +# events below, article_result is emitted at logging verbosity 1. The count +# therefore represents final logged article results in the innreport interval. +section postfilter_ng_results { + title "Postfilter-NG article results:"; + top 50; + data "%postfilter_ng_results"; + sort "$postfilter_ng_results{$b} <=> $postfilter_ng_results{$a} + or $a cmp $b"; + column { + name "Result"; + format "%-12.12s"; + value "(split /\t/, $key, 4)[0]"; + format_total "TOTAL: %-5.5s"; + total "$num"; + }; + column { + name "Action"; + format "%-10.10s"; + value "(split /\t/, $key, 4)[1]"; + format_total "-%9s"; + total ""; + }; + column { + name "Audit"; + format "%5.5s"; + value "(split /\t/, $key, 4)[2]"; + format_total "%4s-"; + total ""; + }; + column { + name "Reason"; + format "%-35.35s"; + value "(split /\t/, $key, 4)[3]"; + format_total "-%34s"; + total ""; + }; + column { + name "Count"; + format_name "%8s"; + format "%8d"; + value "$postfilter_ng_results{$key}"; + total "total(%postfilter_ng_results)"; + }; +}; + +# Overall Postfilter-NG processing time, grouped by final result. This table is +# omitted automatically when timing fields are disabled in Postfilter-NG. +section postfilter_ng_time { + title "Postfilter-NG processing time:"; + data "%postfilter_ng_time_total"; + sort "$postfilter_ng_time_total{$b} <=> $postfilter_ng_time_total{$a} + or $a cmp $b"; + column { + name "Result"; + format "%-12.12s"; + value "$key"; + format_total "TOTAL: %-5.5s"; + total "$num"; + }; + column { + name "Count"; + format_name "%9s"; + format "%9d"; + value "$postfilter_ng_time_count{$key}"; + total "total(%postfilter_ng_time_count)"; + }; + column { + name "Total(ms)"; + format_name "%12s"; + format "%12.3f"; + value "$postfilter_ng_time_total{$key}"; + total "total(%postfilter_ng_time_total)"; + }; + column { + name "Avg(ms)"; + format_name "%10s"; + format "%10.3f"; + value "$postfilter_ng_time_total{$key} / + ($postfilter_ng_time_count{$key} + ? $postfilter_ng_time_count{$key} : 1)"; + total "total(%postfilter_ng_time_count) + ? total(%postfilter_ng_time_total) / + total(%postfilter_ng_time_count) : 0"; + }; + column { + name "Min(ms)"; + format_name "%10s"; + format "%10.3f"; + value "$postfilter_ng_time_min{$key}"; + format_total "%9s-"; + total ""; + }; + column { + name "Max(ms)"; + format_name "%10s"; + format "%10.3f"; + value "$postfilter_ng_time_max{$key}"; + format_total "%9s-"; + total ""; + }; +}; + +# Detailed rule events are emitted only at higher Postfilter-NG verbosity. If +# they are enabled, summarize stable rule IDs without exposing matched values. +section postfilter_ng_rules { + title "Postfilter-NG rule matches:"; + top 50; + data "%postfilter_ng_rules"; + sort "$postfilter_ng_rules{$b} <=> $postfilter_ng_rules{$a} + or $a cmp $b"; + column { + name "Event"; + format "%-20.20s"; + value "(split /\t/, $key, 4)[0]"; + format_total "TOTAL: %-13.13s"; + total "$num"; + }; + column { + name "Action"; + format "%-14.14s"; + value "(split /\t/, $key, 4)[1]"; + format_total "-%13s"; + total ""; + }; + column { + name "Rule"; + format "%-28.28s"; + value "(split /\t/, $key, 4)[2]"; + format_total "-%27s"; + total ""; + }; + column { + name "Target"; + format "%-12.12s"; + value "(split /\t/, $key, 4)[3]"; + format_total "-%11s"; + total ""; + }; + column { + name "Count"; + format_name "%7s"; + format "%7d"; + value "$postfilter_ng_rules{$key}"; + total "total(%postfilter_ng_rules)"; + }; +}; + section innd_perl { title "Perl filter (innd):"; top 20; diff --git a/scripts/innreport_inn.pm b/scripts/innreport_inn.pm index 4b82add..a23459f 100644 --- a/scripts/innreport_inn.pm +++ b/scripts/innreport_inn.pm @@ -296,6 +296,12 @@ our $nocem_lastid; our %nocem_newids; our %nocem_skipids; our %nocem_totalids; +our %postfilter_ng_results; +our %postfilter_ng_rules; +our %postfilter_ng_time_count; +our %postfilter_ng_time_max; +our %postfilter_ng_time_min; +our %postfilter_ng_time_total; our %rnews_bogus_date; our %rnews_bogus_dist; our %rnews_bogus_ng; @@ -338,6 +344,33 @@ foreach (values %nnrpd_timer_names) { } $nnrpd_time_times = 0; # ... +# _postfilter_ng_fields: Extract key="value" fields from a structured +# Postfilter-NG log entry. Logger.pm escapes backslashes and double quotes; +# reverse those escapes here before using the values as report keys. +sub _postfilter_ng_fields($) { + my ($text) = @_; + my %fields; + + while ($text =~ /(?:^|\s)([A-Za-z][A-Za-z0-9_]*)="((?:\\.|[^"\\])*)"/g) + { + my ($key, $value) = ($1, $2); + $value =~ s/\\(["\\])/$1/g; + $fields{$key} = $value; + } + + return \%fields; +} + +# _postfilter_ng_field: Return a usable display value even if a malformed or +# older structured entry omits one of the expected fields. +sub _postfilter_ng_field($$) { + my ($fields, $name) = @_; + + return '(missing)' + if !defined $fields->{$name} || $fields->{$name} eq ''; + return $fields->{$name}; +} + # collect: Used to collect the data. sub collect($$$$$$) { my ($day, $hour, $prog, $res, $left, $CASE_SENSITIVE) = @_; @@ -1651,6 +1684,75 @@ sub collect($$$$$$) { ######## ## nnrpd, nnrpd-ssl, nnrpd-tls if ($prog =~ /^nnrpd(?:-(?:ssl|tls))?$/) { + # Postfilter-NG emits structured key="value" entries through nnrpd. + # article_result is a level-1 event and therefore provides one final + # outcome per logged article. Detailed rule matches are available at + # higher verbosity and are summarized separately when present. + if ($left + =~ /^postfilter-ng (article_result|rule_matched|badword_rule_matched)(?:\s|$)/o) + { + my $event = $1; + my $fields = &_postfilter_ng_fields($left); + + if ($event eq 'article_result') { + my $result = &_postfilter_ng_field($fields, 'result'); + my $action = &_postfilter_ng_field($fields, 'action'); + my $audit = &_postfilter_ng_field($fields, 'audit'); + my $reason = &_postfilter_ng_field($fields, 'reason'); + + $postfilter_ng_results{"$result\t$action\t$audit\t$reason"}++; + + if (defined $fields->{elapsed_ms} + && $fields->{elapsed_ms} =~ /^\d+(?:\.\d+)?$/o) + { + my $elapsed = 0 + $fields->{elapsed_ms}; + $postfilter_ng_time_count{$result}++; + $postfilter_ng_time_total{$result} += $elapsed; + $postfilter_ng_time_min{$result} = $elapsed + if !defined $postfilter_ng_time_min{$result} + || $elapsed < $postfilter_ng_time_min{$result}; + $postfilter_ng_time_max{$result} = $elapsed + if !defined $postfilter_ng_time_max{$result} + || $elapsed > $postfilter_ng_time_max{$result}; + } + } else { + my $action; + if ($event eq 'badword_rule_matched') { + my $score = &_postfilter_ng_field($fields, 'score'); + $action = "score=$score"; + } else { + $action = &_postfilter_ng_field($fields, 'action'); + } + + my $rule = &_postfilter_ng_field($fields, 'rule_id'); + my $target = &_postfilter_ng_field($fields, 'target'); + $postfilter_ng_rules{"$event\t$action\t$rule\t$target"}++; + } + + return 1; + } + # Routine Postfilter-NG lifecycle and high-verbosity diagnostic + # messages. Warnings and errors are deliberately not swallowed so + # that innreport continues to surface operational failures. + return 1 + if $left + =~ /^postfilter-ng\s+(?: + article_identity| + check_completed| + check_skipped| + configuration_generations_pruned| + configuration_loaded| + configuration_reloaded| + custom_filter_loaded| + dns_reputation_query| + header_added| + header_deleted| + header_mime_encoded| + header_pseudonymized| + header_replaced| + phase_completed| + trusted_profile_applied + )(?:\s|$)/ox; # bad_history at num for return 1 if $left =~ /bad_history at \d+ for /o; # timeout short