Finally managed to capture logs of what is happening:
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) LMTP [127.0.0.1]:10024
/var/amavisd/tmp/amavis-20220901T084315-45261-5iOqP3Cd: <a...@example.net> ->
<b...@example.com> SIZE=389475 BODY=7BIT Received: from
mailgate-fra-1.example.com ([127.0.0.1]) by localhost
(mailgate-fra-1.example.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP
for <b...@example.com>; Thu, 1 Sep 2022 08:43:15 +0000 (UTC)
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) Checking: OM-WTN4SH6lR
MYNETS [192.168.48.26] <a...@example.net> -> <b...@example.com>
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) p004 1 Content-Type:
multipart/mixed
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) p005 1/1 Content-Type:
multipart/alternative
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) p001 1/1/1
Content-Type: text/plain, base64, size: 2180, SHA1 digest:
3bde556a0b12548203f0c13f2509987413c4e132
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) p002 1/1/2
Content-Type: text/html, base64, size: 7904, SHA1 digest:
f1f8c7945042797ab77a1e61e6b9617f12c77d16
Sep 1 08:43:15 mailgate-fra-1 amavis[45261]: (45261-01) p003 1/2 Content-Type:
application/pdf, base64, size: 266134, SHA1 digest:
cc1fc0591185baee13566b1fb9ff8ff15292d966, name: JSW Vs Index.pdf
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) _WARN: bayes:
expire_old_tokens: __alarm__ignore__(87/::Plugin::Check::run_eval_tests/1063)
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) SA info: check:
exceeded time limit in
Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_prineg90_set3, skipping
further tests
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) adding recipient -
always_bcc: arch...@archive.example.com, delivery method smtp:[127.0.0.1]:10025
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) dkim: candidate
originators: From:<a...@example.net>
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) dkim: not signing,
empty signing domain, From: <a...@example.net>
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) OM-WTN4SH6lR FWD from
<a...@example.net> -> <b...@example.com>,<arch...@archive.example.com>,
BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as
172644BF03
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) Passed CLEAN
{RelayedInternal}, MYNETS LOCAL [192.168.48.26]:38504 [40.107.104.97]
<a...@example.net> -> <b...@example.com>,<arch...@archive.example.com>,
Queue-ID: A23994BF07, Message-ID:
<am7p192mb0756be867a56b15f37d11f88e7...@example.org>, mail_id: OM-WTN4SH6lR,
Hits: -1.9, size: 389467, queued_as: 172644BF03, 300518 ms
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) TIMING-SA total 300195
ms - parse: 29 (0.0%), extract_message_metadata: 98 (0.0%),
get_uri_detail_list: 4.5 (0.0%), tests_pri_-1000: 25 (0.0%), tests_pri_-950:
1.11 (0.0%), tests_pri_-900: 1.04 (0.0%), tests_pri_-90: 300018 (99.9%),
check_bayes: 300009 (99.9%), b_tokenize: 30 (0.0%), b_tok_get_all: 20 (0.0%),
b_comp_prob: 15 (0.0%), b_tok_touch_all: 1.65 (0.0%), b_finish: 299613 (99.8%),
expire_bayes: 299612 (99.8%), get_report: 1.10 (0.0%)
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) size: 389467, TIMING
[total 300525 ms] - SMTP greeting: 7 (0%)0, SMTP LHLO: 1.2 (0%)0, SMTP
pre-MAIL: 1.2 (0%)0, mkdir tempdir: 2.0 (0%)0, create email.txt: 0.5 (0%)0,
SMTP MAIL: 1.8 (0%)0, SMTP pre-DATA-flush: 2.1 (0%)0, SMTP DATA: 13 (0%)0,
check_init: 0.6 (0%)0, digest_hdr: 3.1 (0%)0, digest_body: 2.3 (0%)0,
collect_info: 8 (0%)0, mkdir parts: 2.0 (0%)0, mime_decode: 47 (0%)0,
get-file-type3: 76 (0%)0, parts_decode: 0.4 (0%)0, check_header: 1.2 (0%)0,
AV-scan-1: 120 (0%)0, spam-wb-list: 1.3 (0%)0, SA parse: 32 (0%)0, SA check:
300162 (100%)100, decide_mail_destiny: 8 (0%)100, notif-quar: 0.4 (0%)100,
fwd-connect: 5 (0%)100, fwd-mail-pip: 1.7 (0%)100, fwd-rcpt-pip: 0.3 (0%)100,
fwd-data-chkpnt: 0.1 (0%)100, write-header: 1.9 (0%)100, fwd-data-contents: 6
(0%)100, fwd-end-chkpnt: 1.6 (0%)100, prepare-dsn: 0.9 (0%)100, report: 1.8
(0%)100, main_log_entry: 7 (0%)100, update_snmp: 1.7 (0%)100, SMTP
pre-response: 0.2 (0%)100, SMTP response: 0.3 (0%)100, u...
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) ...nlink-4-files: 1.3
(0%)100, rundown: 1.4 (0%)100
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) (!!)TROUBLE in
process_request: Error writing an SMTP response to the socket: Broken pipe at
(eval 83) line 1433, <GEN14> line 5279.
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) (!)Requesting process
rundown after fatal error
Sep 1 08:48:16 mailgate-fra-1 amavis[45261]: (45261-01) SMTP shutdown: Error
writing an SMTP response to the socket: at (eval 83) line 1433, <GEN14> line
5279.\\n
The problem is within SpamAssassin (which we had already gathered) but, more
precisely, within
b_finish: 299613 (99.8%), expire_bayes: 299612 (99.8%)
so this finally gives me something specific to look at.
Arrigo
