Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

Postfix queue file write error (amavis?)

102 views
Skip to first unread message

Ulli Horlacher

unread,
Jan 10, 2024, 7:54:14 AM1/10/24
to
Ich bekomme seit 2 Tagen immer wieder mal solche Mails:

From: Mail Delivery System <MAILER-DAEMON@...
To: Postmaster <postmaster@...
Subject: Postfix SMTP server: errors from ...
Date: Wed, 10 Jan 2024 12:15:32 +0100 (CET)

Transcript of session follows.

Out: 220 tandem-fahren.de ESMTP Postfix (Ubuntu)
In: EHLO ...
Out: 250-tandem-fahren.de
Out: 250-PIPELINING
Out: 250-SIZE 33554432
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-DSN
Out: 250 CHUNKING
In: STARTTLS
Out: 220 2.0.0 Ready to start TLS
In: EHLO ...
Out: 250-tandem-fahren.de
Out: 250-PIPELINING
Out: 250-SIZE 33554432
Out: 250-VRFY
Out: 250-ETRN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-DSN
Out: 250 CHUNKING
In: MAIL FROM:<...> SIZE=3403
Out: 250 2.1.0 Ok
In: RCPT TO:<...>
Out: 250 2.1.5 Ok
In: BDAT 2380 LAST
Out: 451 4.3.0 Error: queue file write error

Session aborted, reason: lost connection

For other details, see the local mail logfile


Im mail.log finde ich dazu:

2024-01-10 12:15:32 warning: timeout talking to proxy 127.0.0.1:10024
2024-01-10 12:15:32 proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<...> to=<...> proto=ESMTP helo=<...>


Auf Port laeuft amavis:

root@tandem:/var/log# lsof -i -P | grep 10024
/usr/sbin 41812 amavis 6u IPv4 269812 0t0 TCP localhost:10024 (LISTEN)
/usr/sbin 41812 amavis 7u IPv6 269813 0t0 TCP localhost:10024 (LISTEN)
/usr/sbin 41876 amavis 6u IPv4 269812 0t0 TCP localhost:10024 (LISTEN)
/usr/sbin 41876 amavis 7u IPv6 269813 0t0 TCP localhost:10024 (LISTEN)
/usr/sbin 41877 amavis 6u IPv4 269812 0t0 TCP localhost:10024 (LISTEN)
/usr/sbin 41877 amavis 7u IPv6 269813 0t0 TCP localhost:10024 (LISTEN)

Also hat amavis die Mailannahme verweigert - nur warum?

Dazu finde ich nur im syslog:

2024-01-10 07:08:36 amavis.service: State 'stop-sigterm' timed out. Killing.
2024-01-10 07:08:36 amavis.service: Killing process 33357 (/usr/sbin/amavi) with signal SIGKILL.
2024-01-10 07:08:36 amavis.service: Killing process 33418 (/usr/sbin/amavi) with signal SIGKILL.
2024-01-10 07:08:36 amavis.service: Main process exited, code=killed, status=9/KILL
2024-01-10 07:08:36 amavis.service: Failed with result 'timeout'.
2024-01-10 07:08:36 amavis.service: Consumed 3min 659ms CPU time.
2024-01-10 07:08:57 starting. /usr/sbin/amavisd-new at tandem-fahren.de amavisd-new-2.12.2 (20211013), Unicode aware, LANG="en_US.ISO-8859-15", LC_TIME="en_DK.UTF-8"
2024-01-10 09:18:01 (amavis) CMD (test -e /usr/sbin/amavisd-new-cronjob && /usr/sbin/amavisd-new-cronjob sa-sync)
2024-01-10 12:18:01 (amavis) CMD (test -e /usr/sbin/amavisd-new-cronjob && /usr/sbin/amavisd-new-cronjob sa-sync)

Der Server ist eine VM auf einem host, der teilweise eine sehr hohe load (20..50) hat.
Eventuell ein timing-Problem?

Mails gehen aber anscheinend keine verloren, ich bekomm nur welche doppelt in dem Zeitraum.

--
Ullrich Horlacher Server und Virtualisierung
Rechenzentrum TIK
Universitaet Stuttgart E-Mail: horl...@tik.uni-stuttgart.de
Allmandring 30a Tel: ++49-711-68565868
70569 Stuttgart (Germany) WWW: https://www.tik.uni-stuttgart.de/

Marco Moock

unread,
Jan 10, 2024, 8:03:23 AM1/10/24
to
Am 10.01.2024 um 12:54:12 Uhr schrieb Ulli Horlacher:

> Mails gehen aber anscheinend keine verloren, ich bekomm nur welche
> doppelt in dem Zeitraum.

Die meisten werden auch nicht per BDAT sondern per DATA reinkommen.
Wird denn eine solche Mail, auch wenn mit 4xx abgelehnt, trotzdem
zugestellt bei dir?

Tim Ritberg

unread,
Jan 10, 2024, 9:29:06 AM1/10/24
to
Am 10.01.24 um 13:54 schrieb Ulli Horlacher:

> Also hat amavis die Mailannahme verweigert - nur warum?

Frag Amavis.
log_level auf 1 oder 2

Tim

Ulli Horlacher

unread,
Jan 10, 2024, 9:36:25 AM1/10/24
to
Ja, kommt an, sogar doppelt.

Marco Moock

unread,
Jan 10, 2024, 9:39:24 AM1/10/24
to
Am 10.01.2024 um 14:36:23 Uhr schrieb Ulli Horlacher:

> Marco Moock <mm+s...@dorfdsl.de> wrote:
> > Am 10.01.2024 um 12:54:12 Uhr schrieb Ulli Horlacher:
> >
> >> Mails gehen aber anscheinend keine verloren, ich bekomm nur welche
> >> doppelt in dem Zeitraum.
> >
> > Die meisten werden auch nicht per BDAT sondern per DATA reinkommen.
> > Wird denn eine solche Mail, auch wenn mit 4xx abgelehnt, trotzdem
> > zugestellt bei dir?
>
> Ja, kommt an, sogar doppelt.

Dann ist da was oberfaul, denn 4xx bedeutet, dass die Mail
temporär abgelehnt wird und der andere Server es dann nochmal versucht.

Ulli Horlacher

unread,
Jan 10, 2024, 9:44:59 AM1/10/24
to
Wo stellt man das ein?

root@tandem:/etc/amavis/conf.d# fpg log *

15-av_scanners:
"--log=/var/log/vascan.log {}",
# GeCAD AV technology is acquired by Microsoft; RAV has been discontinued.
"{} -ss -i '*' -log=$MYHOME/vbuster.log", [0], [1],
# '-f -log scandir {}', [0], [3],

20-debian_defaults:
$log_recip_templ = undef; # disable by-recipient level-0 log entries
$DO_SYSLOG = 1; # log via syslogd (preferred)
$syslog_ident = 'amavis'; # syslog ident tag, prepended to all messages
$syslog_facility = 'mail';
$syslog_priority = 'debug'; # switch to info to drop debug output, etc

Tim Ritberg

unread,
Jan 10, 2024, 10:15:47 AM1/10/24
to
Am 10.01.24 um 15:44 schrieb Ulli Horlacher:
> Tim Ritberg <t...@server.invalid> wrote:
>> Am 10.01.24 um 13:54 schrieb Ulli Horlacher:
>>
>>> Also hat amavis die Mailannahme verweigert - nur warum?
>>
>> Frag Amavis.
>> log_level auf 1 oder 2
>
> Wo stellt man das ein?
>
> root@tandem:/etc/amavis/conf.d# fpg log *
>
> 15-av_scanners:
> "--log=/var/log/vascan.log {}",
> # GeCAD AV technology is acquired by Microsoft; RAV has been discontinued.
> "{} -ss -i '*' -log=$MYHOME/vbuster.log", [0], [1],
> # '-f -log scandir {}', [0], [3],
>
> 20-debian_defaults:
> $log_recip_templ = undef; # disable by-recipient level-0 log entries
> $DO_SYSLOG = 1; # log via syslogd (preferred)
> $syslog_ident = 'amavis'; # syslog ident tag, prepended to all messages
> $syslog_facility = 'mail';
> $syslog_priority = 'debug'; # switch to info to drop debug output, etc
>
>

Du hast Debian?
Dann sollte es eine 50-user geben.
$log_level = 1;


Tim

Ulli Horlacher

unread,
Jan 10, 2024, 12:40:09 PM1/10/24
to
Tim Ritberg <t...@server.invalid> wrote:

>>> Frag Amavis.
>>> log_level auf 1 oder 2
>>
>> Wo stellt man das ein?
>>
>> root@tandem:/etc/amavis/conf.d# fpg log *
>>
>> 15-av_scanners:
>> "--log=/var/log/vascan.log {}",
>> # GeCAD AV technology is acquired by Microsoft; RAV has been discontinued.
>> "{} -ss -i '*' -log=$MYHOME/vbuster.log", [0], [1],
>> # '-f -log scandir {}', [0], [3],
>>
>> 20-debian_defaults:
>> $log_recip_templ = undef; # disable by-recipient level-0 log entries
>> $DO_SYSLOG = 1; # log via syslogd (preferred)
>> $syslog_ident = 'amavis'; # syslog ident tag, prepended to all messages
>> $syslog_facility = 'mail';
>> $syslog_priority = 'debug'; # switch to info to drop debug output, etc
>>
>>
>
> Du hast Debian?

Ubuntu, aber das hat wohl dieselbe config.


> Dann sollte es eine 50-user geben.
> $log_level = 1;

Ok, ist drin, nach "service amavis status" steht nun VIEL in
/var/log/mail.log:

2024-01-10 18:27:25 logging initialized, log level 1, syslog: amavis.mail
2024-01-10 18:27:25 starting. /usr/sbin/amavisd-new at tandem-fahren.de amavisd-new-2.12.2 (20211013), Unicode aware, LANG="en_US.I$
2024-01-10 18:27:25 perl=5.034000, user=112, EUID: 112 (112); group=, EGID: 121 119 121 (121 119 121)
2024-01-10 18:27:26 SpamControl: init_pre_chroot on SpamAssassin done
2024-01-10 18:27:26 Net::Server: 2024/01/10-18:27:26 Amavis (type Net::Server::PreForkSimple) starting! pid(49001)
2024-01-10 18:27:26 Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
2024-01-10 18:27:26 Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
2024-01-10 18:27:26 Net::Server: Binding to TCP port 10024 on host ::1 with IPv6
2024-01-10 18:27:26 Net::Server: Group Not Defined. Defaulting to EGID '121 119 121'
2024-01-10 18:27:26 Net::Server: User Not Defined. Defaulting to EUID '112'
2024-01-10 18:27:26 Module Amavis::Conf 2.412
(...)
2024-01-10 18:27:26 Using primary internal av scanner code for ClamAV-clamd
2024-01-10 18:27:26 Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan
2024-01-10 18:27:26 Deleting db files __db.001,snmp.db,__db.003,__db.002,nanny.db in /var/lib/amavis/db
2024-01-10 18:27:26 Creating db in /var/lib/amavis/db/; BerkeleyDB 0.64, libdb 5.3
2024-01-10 18:27:26 initializing Mail::SpamAssassin (0)
2024-01-10 18:27:27 SA info: zoom: able to use 388/388 'body_0' compiled rules (100%)
2024-01-10 18:27:29 SA info: util: setuid: ruid=112 euid=112 rgid=121 119 121 egid=121 119 121
2024-01-10 18:27:29 SpamControl: init_pre_fork on SpamAssassin done
2024-01-10 18:27:29 extra modules loaded after daemonizing/chrooting: /etc/perl/Net/libnet.cfg, Mail/SpamAssassin/CompiledRegexps/body_0.pm, Mail/SpamAssassin/CompiledRegexps/body_neg2000.pm, Mail/SpamAssassin/Plugin/FreeMail.pm, Mail/SpamAssassin/Plugin/SpamCop.pm, Net/Cmd.pm, Net/Config.pm, Net/SMTP.pm

Leider ohne amavis prefix ($syslog_ident). Ich sehe also nicht, ob die
Meldung vom postfix oder von amavis kam.

Noch besser waers, wenn es ein seperates amavis.log gaebe
Aber das ist wohl nicht vorgesehen.
Ich koennte es zwar mit rsyslog abspeichern, aber dafuer braeuchte ich ein
entsprechedes prefix tag in den Meldungen.

Tim Ritberg

unread,
Jan 10, 2024, 1:13:08 PM1/10/24
to
Am 10.01.24 um 18:40 schrieb Ulli Horlacher:
>
> Ok, ist drin, nach "service amavis status" steht nun VIEL in
> /var/log/mail.log:
>

$log_templ = $log_verbose_templ;
kann man noch nehmen. Ich hab beides an.

Tim

Ulli Horlacher

unread,
Jan 11, 2024, 3:47:34 AM1/11/24
to
Was macht das?
Und wie kriegt man eine vernuenftige Markierung hin damit man weiss dass
die Meldung von amavis kam?

Wo findet man Doku zu $log_templ und den anderen config Variablen?
In /usr/share/doc/amavisd-new hab ich nichts gefunden.

In https://www.ijs.si/software/amavisd/README.postfix.html hab ich gefunden:

Nov 1 11:28:10 mail postfix/smtpd[30986]: connect from localhost[127.0.0.1] #
Nov 1 11:28:10 mail postfix/smtpd[30986]: 079474CE44: client=localhost[127.0.0.1]
Nov 1 11:28:10 mail postfix/cleanup[30980]: 079474CE44: message-id=<200611011028...@mail.example.com>
Nov 1 11:28:10 mail postfix/qmgr[20432]: 079474CE44: from=<>, size=822, nrcpt=1 (queue active)
Nov 1 11:28:10 mail amavis[30897]: (30897-02) Passed BAD-HEADER, <> -> <postmaster>, quarantine: badh-le5gjszxowBk, mail_id: le5gjszxowBk, Hits: -1.76, queued_as: 079474CE44, 39505 ms #
Nov 1 11:28:10 mail postfix/smtpd[30986]: disconnect from localhost[127.0.0.1]
Nov 1 11:28:10 mail postfix/local[30987]: 079474CE44: to=<postm...@example.com>, relay=local, delay=0.27, delays=0.14/0.05/0/0.08, dsn=2.0.0, status=sent (delivered to mailbox: postmaster) #
Nov 1 11:28:10 mail postfix/qmgr[20432]: 079474CE44: removed

SO haette ich das auch gerne! Diese prefix-tags fehlen aber bei mir!
Wo schaltet man die an?

Stephan Seitz

unread,
Jan 11, 2024, 4:29:38 AM1/11/24
to
Ulli Horlacher <fram...@rus.uni-stuttgart.de> wrote:
> Out: 451 4.3.0 Error: queue file write error

Zumindest diesen Fehler hatte ich unter Debian 11 auch immer mal von
heute auf morgen. Amavis lief zwar, hat sich aber irgendwie teilweise
geweigert zu arbeiten.

Ein "service amavis stop" hat dann auch nicht alle Prozesse mehr
gekillt. Da gab es noch Kinder, die du mit "kill -9" beenden mußtest.
Danach lief es wieder. Ein "service amavis restart" hat da nicht
geholfen.

Jetzt mit Debian 12 habe ich diesen Fehler noch nicht gehabt.

Stephan

--
| Stephan Seitz E-Mail: stse+...@rootsland.net |
| If your life was a horse, you'd have to shoot it. |

Tim Ritberg

unread,
Jan 11, 2024, 5:00:19 AM1/11/24
to
Am 11.01.24 um 09:47 schrieb Ulli Horlacher:

>
> SO haette ich das auch gerne! Diese prefix-tags fehlen aber bei mir!
> Wo schaltet man die an?

Das liegt sicher nicht an Amavis. Ich habe da nichts besonderes eingestellt.
Da muss du dir deine Config von einem $syslog ansehen.

Tim

Ulli Horlacher

unread,
Jan 12, 2024, 7:12:23 AM1/12/24
to
root@tandem:/etc/rsyslog.d# grep ^mail 50-default.conf
mail.* -/var/log/mail.log
mail.err /var/log/mail.err

Ulli Horlacher

unread,
Jan 12, 2024, 7:57:37 AM1/12/24
to
Ulli Horlacher <fram...@rus.uni-stuttgart.de> wrote:
> Tim Ritberg <t...@server.invalid> wrote:
>> Am 11.01.24 um 09:47 schrieb Ulli Horlacher:
>>
>>>
>>> SO haette ich das auch gerne! Diese prefix-tags fehlen aber bei mir!
>>> Wo schaltet man die an?
>>
>> Das liegt sicher nicht an Amavis. Ich habe da nichts besonderes eingestellt.
>> Da muss du dir deine Config von einem $syslog ansehen.
>
> root@tandem:/etc/rsyslog.d# grep ^mail 50-default.conf
> mail.* -/var/log/mail.log
> mail.err /var/log/mail.err

Falsche Stelle. Habs:

root@tandem:/etc/rsyslog.d# vv -d 8 00-isodate.conf
--- .versions/00-isodate.conf~08~ 2017-10-25 16:11:19.000000000 +0200
+++ 00-isodate.conf 2024-01-12 13:48:36.632869465 +0100
@@ -1,2 +1,3 @@
-$template ISO8601,"%timereported:::date-pgsql% %msg%\n"
+# https://www.rsyslog.com/doc/configuration/properties.html
+$template ISO8601,"%timereported:::date-pgsql% %syslogtag%%msg%\n"
$ActionFileDefaultTemplate ISO8601

%syslogtag% fehlte!
0 new messages