When I try to send mails on my mailcow instance (SOGo or IMAP), I often do see the following error: “4.7.1 timeout post-processing message;”
After inspecting the logs I also do see some incomming mails being soft-rejected due to this error.
Upon further digging into the logs I could isolate the following log entries:
Unsuccessful attempt:
postfix: (prior to rspamd)
postfix-mailcow_1 | Jan 20 10:00:59 cdc03c87af0a postfix/sogo/smtpd[74896]: 197001C56F0: client=xxx_sogo-mailcow_1.xxx_mailcow-network[172.22.1.248], sasl_method=PLAIN, sasl_username=xxx@xxx.net
postfix-mailcow_1 | Jan 20 10:00:59 cdc03c87af0a postfix/cleanup[74900]: 197001C56F0: replace: header Received: from 677d29bfe31f (xxx_sogo-mailcow_1.xxx_mailcow-network [172.22.1.248])??(Authenticated sender: xxx@xxx.net)??by mail.xxx.net (Postcow) with ESMTPA id 197001C56F0??for from xxx_sogo-mailcow_1.xxx_mailcow-network[172.22.1.248]; from=<xxx@xxx.net> to=<xxx@gmx.net> proto=ESMTP helo=<677d29bfe31f>: Received: from [127.0.0.1] (localhost [127.0.0.1]) by localhost (Mailerdaemon) with ESMTPA id 197001C56F0??for <xxx@gmx.net>; Thu, 20 Jan 2022 10:00:58 +0100 (CET)
postfix-mailcow_1 | Jan 20 10:00:59 cdc03c87af0a postfix/cleanup[74900]: 197001C56F0: message-id=<8c862-61e92500-1-3a655380@153959994>
rspamd:
rspamd-mailcow_1 | 2022-01-20 10:01:06 #46(normal) <7cc405>; lua; clamav.lua:119: clamav: failed to scan, maximum retransmits exceed
rspamd-mailcow_1 | 2022-01-20 10:01:37 #46(normal) <7cc405>; task; rspamd_task_write_log: id: <8c862-61e92500-1-3a655380@153959994>, qid: <197001C56F0>, ip: 172.22.1.248, user: xxx@xxx.net, from: <xxx@xxx.net>, (default: F (soft reject): [-31.09/15.00] [MAILCOW_AUTH(-20.00){},BAYES_HAM(-5.49){99.99%;},NEURAL_HAM_LONG(-4.00){-1.000;},NEURAL_HAM_SHORT(-2.00){-1.000;},MID_RHS_NOT_FQDN(0.50){},MIME_GOOD(-0.10){multipart/mixed;multipart/alternative;text/plain;},ARC_NA(0.00){},CLAM_VIRUS_FAIL(0.00){failed to scan and retransmits exceed;},DKIM_SIGNED(0.00){xxx.net:s=dkim;},DYN_RL_CHECK(0.00){},FREEMAIL_ENVRCPT(0.00){gmx.net;},FREEMAIL_TO(0.00){gmx.net;},FROM_EQ_ENVFROM(0.00){},FROM_HAS_DN(0.00){},HAS_ATTACHMENT(0.00){},MAILCOW_DOMAIN_HEADER_FROM(0.00){xxx.net;},MIME_TRACE(0.00){0:+;1:+;2:+;3:~;4:~;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_ZERO(0.00){0;},TO_DN_NONE(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){}]), len: 78779, time: 38188.928ms, dns req: 9, digest: <8ca759f87dc70cffdaa042324be48922>, rcpts: <xxx@gmx.net>, mime_rcpts: <xxx@gmx.net>, forced: soft reject "timeout post-processing message"; score=nan (set by task timeout)
rspamd-mailcow_1 | 2022-01-20 10:01:37 #46(normal) <7cc405>; task; rspamd_protocol_http_reply: regexp statistics: 0 pcre regexps scanned, 6 regexps matched, 3174 regexps total, 2881 regexps cached, 0B scanned using pcre, 1.83KiB scanned total
postfix: (after to rspamd)
postfix-mailcow_1 | Jan 20 10:01:37 cdc03c87af0a postfix/cleanup[74900]: 197001C56F0: milter-reject: END-OF-MESSAGE from xxx_sogo-mailcow_1.xxx_mailcow-network[172.22.1.248]: 4.7.1 timeout post-processing message; from=<xxx@xxx.net> to=<xxx@gmx.net> proto=ESMTP helo=<677d29bfe31f>
Successful attempt:
postfix: (prior to rspamd)
postfix-mailcow_1 | Jan 20 10:01:57 cdc03c87af0a postfix/sogo/smtpd[74896]: 23AA51C0313: client=xxx_sogo-mailcow_1.xxx_mailcow-network[172.22.1.248], sasl_method=PLAIN, sasl_username=xxx@xxx.net
postfix-mailcow_1 | Jan 20 10:01:57 cdc03c87af0a postfix/cleanup[74900]: 23AA51C0313: replace: header Received: from 677d29bfe31f (xxx_sogo-mailcow_1.xxx_mailcow-network [172.22.1.248])??(Authenticated sender: xxx@xxx.net)??by mail.xxx.net (Postcow) with ESMTPA id 23AA51C0313??for from xxx_sogo-mailcow_1.xxx_mailcow-network[172.22.1.248]; from=<xxx@xxx.net> to=<xxx@gmx.net> proto=ESMTP helo=<677d29bfe31f>: Received: from [127.0.0.1] (localhost [127.0.0.1]) by localhost (Mailerdaemon) with ESMTPA id 23AA51C0313??for <xxx@gmx.net>; Thu, 20 Jan 2022 10:01:57 +0100 (CET)
postfix-mailcow_1 | Jan 20 10:01:57 cdc03c87af0a postfix/cleanup[74900]: 23AA51C0313: message-id=<850b1-61e92500-3-2a47fe00@121471870>
rspamd:
rspamd-mailcow_1 | 2022-01-20 10:01:57 #46(normal) <96247a>; lua; clamav.lua:119: clamav: failed to scan, maximum retransmits exceed
rspamd-mailcow_1 | 2022-01-20 10:01:58 #46(normal) <96247a>; task; rspamd_task_write_log: id: <850b1-61e92500-3-2a47fe00@121471870>, qid: <23AA51C0313>, ip: 172.22.1.248, user: xxx@xxx.net, from: <xxx@xxx.net>, (default: F (no action): [-31.09/15.00] [MAILCOW_AUTH(-20.00){},BAYES_HAM(-5.49){99.99%;},NEURAL_HAM_LONG(-4.00){-1.000;},NEURAL_HAM_SHORT(-2.00){-1.000;},MID_RHS_NOT_FQDN(0.50){},MIME_GOOD(-0.10){multipart/mixed;multipart/alternative;text/plain;},ARC_NA(0.00){},BCC(0.00){},CLAM_VIRUS_FAIL(0.00){failed to scan and retransmits exceed;},DKIM_SIGNED(0.00){xxx.net:s=dkim;},DYN_RL_CHECK(0.00){},FREEMAIL_ENVRCPT(0.00){gmx.net;},FREEMAIL_TO(0.00){gmx.net;},FROM_EQ_ENVFROM(0.00){},FROM_HAS_DN(0.00){},HAS_ATTACHMENT(0.00){},MAILCOW_DOMAIN_HEADER_FROM(0.00){xxx.net;},MIME_TRACE(0.00){0:+;1:+;2:+;3:~;4:~;},RCPT_COUNT_ONE(0.00){1;},RCVD_COUNT_ZERO(0.00){0;},TO_DN_NONE(0.00){},TO_MATCH_ENVRCPT_ALL(0.00){}]), len: 78779, time: 1185.431ms, dns req: 13, digest: <8ca759f87dc70cffdaa042324be48922>, rcpts: <xxx@gmx.net>, mime_rcpts: <xxx@gmx.net>
rspamd-mailcow_1 | 2022-01-20 10:01:58 #46(normal) <96247a>; task; rspamd_protocol_http_reply: regexp statistics: 0 pcre regexps scanned, 6 regexps matched, 3174 regexps total, 2881 regexps cached, 0B scanned using pcre, 1.83KiB scanned total
postfix: (after to rspamd)
postfix-mailcow_1 | Jan 20 10:01:58 cdc03c87af0a postfix/qmgr[386]: 23AA51C0313: from=<xxx@xxx.net>, size=78986, nrcpt=1 (queue active)
postfix-mailcow_1 | Jan 20 10:01:59 cdc03c87af0a postfix/smtp[74910]: 23AA51C0313: to=<xxx@gmx.net>, relay=mx01.emig.gmx.net[212.227.17.5]:25, delay=2.9, delays=1.3/0.41/0.37/0.73, dsn=2.0.0, status=sent (250 Requested mail action okay, completed: id=1Mybzx-1mMvaE1CBB-00z2mW)
postfix-mailcow_1 | Jan 20 10:01:59 cdc03c87af0a postfix/qmgr[386]: 23AA51C0313: removed
Based on the logs I see that rspamd take over 30 seconds to process that rather tiny mail, whilst doing 9 DNS requests: time: 38188.928ms, dns req: 9
Directly retrying to send the mail works however: time: 1185.431ms, dns req: 13
I do not see any errors in the unbound log.
Has anyone an idea or a suggestion for a fix?
Thanks!