do_log(2, "...") for nonspam messages not implemented anymore in 2.7.0?

[Mark Martinec]

Frank,

> up to and including 2.6.6 amavisd-new did log nonspam messages in
> syslog as well like for example:
> 
> Oct 31 21:47:50 amazone amavis[1347]: (01347-03) SPAM-TAG, <AAAAA at XXXXX>
> -> <frank at undermydesk.org>, No, score=2.984 tagged_above=-999 required=5
> tests=[DELIVERY_TIMING=-0.001, EXTRA_MPART_TYPE=1, HTML_MESSAGE=0.001,
> PYZOR_CHECK=1.985, SPF_PASS=-0.001, T_KHOP_FOREIGN_CLICK=0.01,
> T_RP_MATCHES_RCVD=-0.01] autolearn=disabled

That log entry was just a debugging aid, logged at log level 2.

> This feature obviously doesn't work anymore with 2.7.0 - because
> the do_log sub gets called on spam messages only as the
> code suggests.
> nonspam messages don't call do_log in this way (they only add
> proper headers with the tests).
> 
> Can we please resurrect the 'old' behaviour?

The usual way of getting the list of triggered rules in the log is
by adding a %T macro call into a log template, either by editing
a default template near the end of a file amavisd (uncommenting
the already provided line with a %T, twice), search for:
  This text section governs how a main per-message amavisd-new log entry
in a file amavisd,  or more cleanly, by assigning a custom template
to a variable $log_templ in a config file, e.g.:

$log_templ = <<'EOD';
[?%#D|#|Passed #
[? [:ccat|major] |#
OTHER|CLEAN|MTA-BLOCKED|OVERSIZED|BAD-HEADER-[:ccat|minor]|SPAMMY|SPAM|\
UNCHECKED|BANNED (%F)|INFECTED (%V)] {[:actions_performed]}#
, [? %p ||%p ][?%a||[?%l||LOCAL ][:client_addr_port] ][?%e||\[%e\] ]%s -> [%D|,]#
[? %q ||, quarantine: %q]#
[? %Q ||, Queue-ID: %Q]#
[? %m ||, Message-ID: %m]#
[? %r ||, Resent-Message-ID: %r]#
[? %i ||, mail_id: %i]#
, Hits: [:SCORE]#
, size: %z#
[? [:partition_tag] ||, pt: [:partition_tag]]#
[~[:remote_mta_smtp_response]|["^$"]||[", queued_as: "]]\
[remote_mta_smtp_response|[~%x|["queued as ([0-9A-Za-z]+)$"]|["%1"]|["%0"]]|/]#
#[? [:header_field|Subject]||, Subject: [:dquote|[:mime2utf8|[:header_field|Subject]|100|1]]]#
#[? [:header_field|From]||, From: [:uquote|[:mime2utf8|[:header_field|From]|100|1]]]#
[? %#T ||, Tests: \[[%T|,]\]]#
[? [:dkim|sig_sd]    ||, dkim_sd=[:dkim|sig_sd]]#
[? [:dkim|newsig_sd] ||, dkim_new=[:dkim|newsig_sd]]#
, %y ms#
]
[?%#O|#|Blocked #
[? [:ccat|major|blocking] |#
OTHER|CLEAN|MTA-BLOCKED|OVERSIZED|BAD-HEADER-[:ccat|minor]|SPAMMY|SPAM|\
UNCHECKED|BANNED (%F)|INFECTED (%V)] {[:actions_performed]}#
, [? %p ||%p ][?%a||[?%l||LOCAL ][:client_addr_port] ][?%e||\[%e\] ]%s -> [%O|,]#
[? %q ||, quarantine: %q]#
[? %Q ||, Queue-ID: %Q]#
[? %m ||, Message-ID: %m]#
[? %r ||, Resent-Message-ID: %r]#
[? %i ||, mail_id: %i]#
, Hits: [:SCORE]#
, size: %z#
[? [:partition_tag] ||, pt: [:partition_tag]]#
#[? [:header_field|Subject]||, Subject: [:dquote|[:mime2utf8|[:header_field|Subject]|100|1]]]#
#[? [:header_field|From]||, From: [:uquote|[:mime2utf8|[:header_field|From]|100|1]]]#
[? %#T ||, Tests: \[[%T|,]\]]#
[? [:dkim|sig_sd]    ||, dkim_sd=[:dkim|sig_sd]]#
[? [:dkim|newsig_sd] ||, dkim_new=[:dkim|newsig_sd]]#
, %y ms#
]
EOD


> The current code even suggests that it's probably only missing
> by mistake

Intentionally. I was eager to get rid if it - it was a reason people tried
to parse debug-level logging and then complained if these entries
changed between versions. Having all the information available at
log level 0 removed a need to keep and to parse deeper-levels of
logging.

  Mark