postfix queue file write error / amavis Can't allocate memory

[Ulli Horlacher]

Ich bekomme auf einem meiner Systeme immer wieder mal solche Mails:


From: Mail Delivery System <MAILER-***@ZZZZZZ.ZZ>
To: Postmaster <***@ZZZZZZ.ZZ>
Subject: Postfix SMTP server: errors from
mail-pg1-f196.google.com[209.85.215.196]
Date: Tue, 12 Mar 2024 10:26:33 +0100 (CET)

Transcript of session follows.

Out: 220 ZZZZZZ.ZZ ESMTP Postfix (Ubuntu)
In: EHLO mail-pg1-f196.google.com
Out: 250-ZZZZZZ.ZZ
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 mail-pg1-f196.google.com
Out: 250-ZZZZZZ.ZZ
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:<***@gmail.com> SIZE=8489
Out: 250 2.1.0 Ok
In: RCPT TO:<***@ZZZZZZ.ZZ>
Out: 250 2.1.5 Ok
In: BDAT 8489 LAST
Out: 451 4.3.0 Error: queue file write error
In: QUIT
Out: 221 2.0.0 Bye


For other details, see the local mail logfile


***@zzzzzz:/var/log# cat mail.err
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!!)AV: ALL VIRUS SCANNERS FAILED

***@zzzzzz:/var/log# grep ' 10:27' mail.log
2024-03-12 10:27:21 amavis[52116]: (52116-01) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 124) line 657.\n
2024-03-12 10:27:21 amavis[52116]: (52116-01) (!)WARN: all primary virus scanners failed, considering backups
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!)run_av (ClamAV-clamscan) FAILED - unexpected exit 2, output="LibClamAV Error: mpool_malloc(): Can't allocate memory (262144 bytes).\nLibClamAV Error: cli_mpool_strdup(): Can't allocate memory (28 bytes).\nLibClamAV Error: cli_loadhash: Problem parsing database at line 367034\nLibClamAV Error: Can't load daily.hsb: Malformed database\nLibClamAV Error: cli_tgzload: Can't load daily.hsb\nLibClamAV Error: Can't load /var/lib/clamav/daily.cld: Malformed database\nLibClamAV Error: cli_loaddbdir(): error loading database /var/lib/clamav/daily.cld\nERROR: Malformed database"
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!)ClamAV-clamscan av-scanner FAILED: /usr/bin/clamscan unexpected exit 2, output="LibClamAV Error: mpool_malloc(): Can't allocate memory (262144 bytes).\nLibClamAV Error: cli_mpool_strdup(): Can't allocate memory (28 bytes).\nLibClamAV Error: cli_loadhash: Problem parsing database at line 367034\nLibClamAV Error: Can't load daily.hsb: Malformed database\nLibClamAV Error: cli_tgzload: Can't load daily.hsb\nLibClamAV Error: Can't load /var/lib/clamav/daily.cld: Malformed database\nLibClamAV Error: cli_loaddbdir(): error loading database /var/lib/clamav/daily.cld\nERROR: Malformed database" at (eval 124) line 951.
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!!)AV: ALL VIRUS SCANNERS FAILED
2024-03-12 10:27:36 amavis[53998]: (52116-01) SA info: util: setuid: ruid=112 euid=112 rgid=121 119 121 egid=121 119 121
2024-03-12 10:27:36 amavis[52116]: (52116-01) Blocked SPAM {RejectedInbound}, [209.85.215.196]:51315 [209.85.215.196] <***@gmail.com> -> <***@ZZZZZZ.ZZ>, Message-ID: <CAJoHSaGkFiwVhjnhJkzyWusZKGYt1b_AfKCy-Zm76CC3Q5+-***@mail.gmail.com>, mail_id: OlY3GFNNwphy, Hits: 7.378, size: 8691, dkim_sd=20230601:gmail.com, 303784 ms

***@zzzzzz:/var/log# free -h
total used free shared buff/cache available
Mem: 5.8Gi 2.1Gi 1.6Gi 1.0Mi 2.1Gi 3.4Gi
Swap: 0B 0B 0B


Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

[Marco Moock]

Post by Ulli Horlacher
In: BDAT 8489 LAST

Schalte mal testweise BDAT/CHUNKING ab und teste, ob das weiterhin
auftritt.

[Tim Ritberg]

Post by Ulli Horlacher
Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

Was sagt: cat /proc/sys/vm/overcommit_memory?

Tim

[Ulli Horlacher]

Post by Tim Ritberg

Post by Ulli Horlacher
Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

Was sagt: cat /proc/sys/vm/overcommit_memory?

2

Aber es ist eigentlich immer genug Speicher da:

total used free shared buff/cache available
Mem: 5.8Gi 2.1Gi 1.2Gi 3.0Mi 2.5Gi 3.4Gi
Swap: 0B 0B 0B

[Tim Ritberg]

Post by Ulli Horlacher

Post by Tim Ritberg

Post by Ulli Horlacher
Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

Was sagt: cat /proc/sys/vm/overcommit_memory?

2
total used free shared buff/cache available
Mem: 5.8Gi 2.1Gi 1.2Gi 3.0Mi 2.5Gi 3.4Gi
Swap: 0B 0B 0B

Nope. Diese Anzeige zeigt das Problem nicht:
https://www.kernel.org/doc/Documentation/vm/overcommit-accounting

Stell auf 0 und das Problem müsste weg sein.

Tim

[Peter J. Holzer]

Post by Tim Ritberg

Post by Ulli Horlacher

Post by Tim Ritberg

Post by Ulli Horlacher
Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

Was sagt: cat /proc/sys/vm/overcommit_memory?

2
total used free shared buff/cache available
Mem: 5.8Gi 2.1Gi 1.2Gi 3.0Mi 2.5Gi 3.4Gi
Swap: 0B 0B 0B

https://www.kernel.org/doc/Documentation/vm/overcommit-accounting

Zitat:

| 2 - Don't overcommit. The total address space commit
| for the system is not permitted to exceed swap + a
| configurable amount (default is 50%) of physical RAM.

Hier also 0 GB + 5.8 GB * 0.5 = 2.9 GB.

Zum Zeitpunkt des Aufrufs waren 2.1 GB "used". Reserviertes Virtual
Memory ist vermutlich um einiges größer, die Wahrscheinlichkeit, dass
das vor einiger Zeit an der 2.9 GB-Grenze angestoßen ist, ist also nicht
vernachlässigbar.

Post by Tim Ritberg
Stell auf 0 und das Problem müsste weg sein.

Alternativ könnte man auch an vm.overcommit_ratio bzw.
vm.overcommit_kbytes drehen und/oder dem System ein bisschen Swapspace
gönnen.

Aber es hat schon seinen Grund, warum overcommit_memory=0 der Default
ist.

hp

[Peter J. Holzer]

[...]

Post by Ulli Horlacher
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!)run_av (ClamAV-clamscan) FAILED - unexpected exit 2, output="LibClamAV Error: mpool_malloc(): Can't allocate memory (262144 bytes).\nLibClamAV Error: cli_mpool_strdup(): Can't allocate memory (28 bytes).\nLibClamAV Error: cli_loadhash: Problem parsing database at line 367034\nLibClamAV Error: Can't load daily.hsb: Malformed database\nLibClamAV Error: cli_tgzload: Can't load daily.hsb\nLibClamAV Error: Can't load /var/lib/clamav/daily.cld: Malformed database\nLibClamAV Error: cli_loaddbdir(): error loading database /var/lib/clamav/daily.cld\nERROR: Malformed database"
2024-03-12 10:27:33 amavis[52116]: (52116-01) (!)ClamAV-clamscan av-scanner FAILED: /usr/bin/clamscan unexpected exit 2, output="LibClamAV Error: mpool_malloc(): Can't allocate memory (262144 bytes).\nLibClamAV Error: cli_mpool_strdup(): Can't allocate memory (28 bytes).\nLibClamAV Error: cli_loadhash: Problem parsing database at line 367034\nLibClamAV Error: Can't load daily.hsb: Malformed database\nLibClamAV Error: cli_tgzload: Can't load daily.hsb\nLibClamAV Error: Can't load /var/lib/clamav/daily.cld: Malformed database\nLibClamAV Error: cli_loaddbdir(): error loading database /var/lib/clamav/daily.cld\nERROR: Malformed database" at (eval 124) line 951.

[...]

Post by Ulli Horlacher
total used free shared buff/cache available
Mem: 5.8Gi 2.1Gi 1.6Gi 1.0Mi 2.1Gi 3.4Gi
Swap: 0B 0B 0B
Wieso "Can't allocate memory (262144 bytes)"? 260 kB?!?

256. Dürfte wohl die Chunk-Größe des Allokators sein. Das ist nicht die
Gesamtgröße des Prozesses, sondern die Größe des Requests, der nicht
mehr bedient werden konnte (quasi der Tropfen, der das Fass zum
Überlaufen brachte).

Läuft ClamAV vielleicht mit restriktiven Resource-Limits?

hp

[Tim Ritberg]

Post by Peter J. Holzer
256. Dürfte wohl die Chunk-Größe des Allokators sein. Das ist nicht die
Gesamtgröße des Prozesses, sondern die Größe des Requests, der nicht
mehr bedient werden konnte (quasi der Tropfen, der das Fass zum
Überlaufen brachte).
Läuft ClamAV vielleicht mit restriktiven Resource-Limits?
hp

So sieht einer meiner MXer nur mit Postfix, Amavis mit Spamassassin und
ClamAV aus:
Loading Image...

2 GB Ram + Swap und ohne Swap würde es gar nicht laufen.

Tim