[GH-ISSUE #2475] Amavis crashed every 20 messages: (!)Amavis::END: DB unregistering failed #1611

Closed
opened 2026-02-27 11:18:05 +03:00 by kerem · 42 comments
Owner

Originally created by @gianks on GitHub (Mar 16, 2022).
Original GitHub issue: https://github.com/modoboa/modoboa/issues/2475

Impacted versions

1.17.0

  • OS Type: Debian
  • OS Version: 11
  • Database Type: PostgreSQL
  • Database version: X.y
  • Modoboa: 1.17.0
  • installer used: Yes
  • Webserver: Nginx

Steps to reproduce

Receive 20 or more emails.

Current behavior

Repeated tests show
Amavis crashing exactly after 20 processed emails with message:
amavis[XX]: (XX-20) (!)Amavis::END: DB unregistering failed:

Expected behavior

Amavis keeps running without any intervention.

Video/Screenshot link (optional)

Originally created by @gianks on GitHub (Mar 16, 2022). Original GitHub issue: https://github.com/modoboa/modoboa/issues/2475 # Impacted versions 1.17.0 * OS Type: Debian * OS Version: 11 * Database Type: PostgreSQL * Database version: X.y * Modoboa: 1.17.0 * installer used: Yes * Webserver: Nginx # Steps to reproduce Receive 20 or more emails. # Current behavior Repeated tests show Amavis crashing exactly after 20 processed emails with message: amavis[XX]: (XX-20) (!)Amavis::END: DB unregistering failed: # Expected behavior Amavis keeps running without any intervention. # Video/Screenshot link (optional)
kerem closed this issue 2026-02-27 11:18:05 +03:00
Author
Owner

@gianks commented on GitHub (Mar 16, 2022):

A possible solution seems to be setting $max_server = 2 instead of 1 in /etc/amavis/conf.d/50-user (generated by modoboa).
I did not investigate extensively why, but the magical number 20 is defined within amavis-new scritp, as maximum child requests.

I suspect that using a single server the program terminates when the first child arrives at 20 instead of spawning a new one, but it's just a guess.

<!-- gh-comment-id:1069117032 --> @gianks commented on GitHub (Mar 16, 2022): A possible solution seems to be setting $max_server = 2 instead of 1 in /etc/amavis/conf.d/50-user (generated by modoboa). I did not investigate extensively why, but the magical number 20 is defined within amavis-new scritp, as maximum child requests. I suspect that using a single server the program terminates when the first child arrives at 20 instead of spawning a new one, but it's just a guess.
Author
Owner

@vingeni commented on GitHub (Mar 21, 2022):

Hi,
I got the same issue, as a workaround I added two lines into the service file /etc/systemd/system/multi-user.target.wants/amavis.service to restart the service:

[Service]
+Restart=always
+RestartSec=3
<!-- gh-comment-id:1073865261 --> @vingeni commented on GitHub (Mar 21, 2022): Hi, I got the same issue, as a workaround I added two lines into the service file ```/etc/systemd/system/multi-user.target.wants/amavis.service``` to restart the service: ``` [Service] +Restart=always +RestartSec=3 ```
Author
Owner

@MrGeneration commented on GitHub (Mar 24, 2022):

How much system ressources did you provide your modoboa machine?

<!-- gh-comment-id:1077624107 --> @MrGeneration commented on GitHub (Mar 24, 2022): How much system ressources did you provide your modoboa machine?
Author
Owner

@stale[bot] commented on GitHub (May 25, 2022):

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

<!-- gh-comment-id:1137857272 --> @stale[bot] commented on GitHub (May 25, 2022): This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
Author
Owner

@blackhold commented on GitHub (Jun 10, 2022):

Hello, I had the same problem in debian 11.3 with installer, I fixed incrementing $max_server = 2 in /etc/amavis/conf.d/50-user, at the moment I don't have to apply systemd configuration as mentioned by vingeni.

<!-- gh-comment-id:1152471779 --> @blackhold commented on GitHub (Jun 10, 2022): Hello, I had the same problem in debian 11.3 with installer, I fixed incrementing $max_server = 2 in /etc/amavis/conf.d/50-user, at the moment I don't have to apply systemd configuration as mentioned by vingeni.
Author
Owner

@IppyD commented on GitHub (Jun 27, 2022):

Same issue here. Lots of resources available in principle for one domain/~30 mailboxes, but amavis was restarting - and Monit reporting it - quite manically. I doubled memory, pursued the logs and eventually arrived here. No reports since setting $max_server = 2.

However I did note that this value is reported to need to match the value in postfix configuration (see, eg here: https://docs.iredmail.org/concurrent.processing.html ). That is smtp-amavis value should equal $max_server value.

I couldn't actually find this config value though. Is it true? Did I misunderstand?

<!-- gh-comment-id:1167503917 --> @IppyD commented on GitHub (Jun 27, 2022): Same issue here. Lots of resources available in principle for one domain/~30 mailboxes, but amavis was restarting - and Monit reporting it - quite manically. I doubled memory, pursued the logs and eventually arrived here. No reports since setting `$max_server = 2. ` However I did note that this value is reported to need to match the value in postfix configuration (see, eg here: https://docs.iredmail.org/concurrent.processing.html ). That is `smtp-amavis` value should equal `$max_server` value. I couldn't actually find this config value though. Is it true? Did I misunderstand?
Author
Owner

@Spitfireap commented on GitHub (Jul 17, 2022):

same issue here, it crashes after 20 mails, I've set up the max_server to 2 to see if it works. @IppyD did you try adding smtp-amavis_destination_concurrency_limit = 2 to main.cf maybe ?

<!-- gh-comment-id:1186577835 --> @Spitfireap commented on GitHub (Jul 17, 2022): same issue here, it crashes after 20 mails, I've set up the max_server to 2 to see if it works. @IppyD did you try adding ``smtp-amavis_destination_concurrency_limit = 2`` to main.cf maybe ?
Author
Owner

@nicosqc commented on GitHub (Jul 21, 2022):

not sure if related, but on my machine with 8GB RAM and 6 cpu cores I did set $max_servers to 8 and now I have no more timeout problems on load. Before, if I sent 5-10MB .exe files to 10 different aliases on my machine half of the mails would time out and the other mailserver would resend half of them because they had the "mail queue write error" aka postfix/smtpd[3972]: warning: timeout talking to proxy inet:[127.0.0.1]:10024

However I did note that this value is reported to need to match the value in postfix configuration (see, eg here: https://docs.iredmail.org/concurrent.processing.html ). That is smtp-amavis value should equal $max_server value.

I was looking into this too, I checked both master and main.cf and I could not identify the service used for amavis. There is a flag -o smtpd_proxy_options=speed_adjust after -o smtpd_proxy_filter=inet:[127.0.0.1]:10024 with smtpd so I guess this is what automatically adjusts the amount of instances that are spun up. Either way, it works fine without either configuration change. To my understanding adding smtp-amavis_destination_concurrency_limit = 2 would serve no purpose since there is no smtp-amavis service this would refer to

<!-- gh-comment-id:1191507422 --> @nicosqc commented on GitHub (Jul 21, 2022): not sure if related, but on my machine with 8GB RAM and 6 cpu cores I did set $max_servers to 8 and now I have no more timeout problems on load. Before, if I sent 5-10MB .exe files to 10 different aliases on my machine half of the mails would time out and the other mailserver would resend half of them because they had the "mail queue write error" aka `postfix/smtpd[3972]: warning: timeout talking to proxy inet:[127.0.0.1]:10024` > However I did note that this value is reported to need to match the value in postfix configuration (see, eg here: https://docs.iredmail.org/concurrent.processing.html ). That is smtp-amavis value should equal $max_server value. I was looking into this too, I checked both master and main.cf and I could not identify the service used for amavis. There is a flag `-o smtpd_proxy_options=speed_adjust` after ` -o smtpd_proxy_filter=inet:[127.0.0.1]:10024` with smtpd so I guess this is what automatically adjusts the amount of instances that are spun up. Either way, it works fine without either configuration change. To my understanding adding `smtp-amavis_destination_concurrency_limit = 2` would serve no purpose since there is no smtp-amavis service this would refer to
Author
Owner

@stale[bot] commented on GitHub (Sep 20, 2022):

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

<!-- gh-comment-id:1252617967 --> @stale[bot] commented on GitHub (Sep 20, 2022): This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
Author
Owner

@stefaweb commented on GitHub (Sep 28, 2022):

Hello,

I started to receive tens of "Out: 451 4.3.0 Error: queue file write error" mail from the new 2.0.2 Modoboa server I just installed. I installed the "lmtp patch" (using description in https://github.com/modoboa/modoboa-installer/pull/425).

It seems that it fails as soon as the server receives more than two or three mails at the same time. However, I have a correct server with 8Go of RAM.

Regards,

<!-- gh-comment-id:1261131185 --> @stefaweb commented on GitHub (Sep 28, 2022): Hello, I started to receive tens of "Out: 451 4.3.0 Error: queue file write error" mail from the new 2.0.2 Modoboa server I just installed. I installed the "lmtp patch" (using description in https://github.com/modoboa/modoboa-installer/pull/425). It seems that it fails as soon as the server receives more than two or three mails at the same time. However, I have a correct server with 8Go of RAM. Regards,
Author
Owner

@stefaweb commented on GitHub (Sep 29, 2022):

Hello,

No more error since yesterday.

I think it would be better to have the configuration using lmtp by default because it seems that even with few messages coming to the server, the system through the proxy seems unreliable.

Regards,

<!-- gh-comment-id:1262056323 --> @stefaweb commented on GitHub (Sep 29, 2022): Hello, No more error since yesterday. I think it would be better to have the configuration using lmtp by default because it seems that even with few messages coming to the server, the system through the proxy seems unreliable. Regards,
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

FYI: https://www.postfix.org/SMTPD_PROXY_README.html#pros_cons

<!-- gh-comment-id:1263221073 --> @tonioo commented on GitHub (Sep 30, 2022): FYI: https://www.postfix.org/SMTPD_PROXY_README.html#pros_cons
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

Hello,

The server is an Scaleway VM cloud instance (PRO2-XXS) with 2 cores 64Bits, SSD block storage and 8Go de RAM. No swap. System is Debian bullseye uptodate.

I tried again yesterday with the default proxy setup. The system crashes and loses mails as soon as more than 2 or 3 mails are processed at the same time. Whether they come from an auth login or not. The worst is that we are not warned. We just see it in mail.log.

Regards,

<!-- gh-comment-id:1263237924 --> @stefaweb commented on GitHub (Sep 30, 2022): Hello, The server is an Scaleway VM cloud instance (PRO2-XXS) with 2 cores 64Bits, SSD block storage and 8Go de RAM. No swap. System is Debian bullseye uptodate. I tried again yesterday with the default proxy setup. The system crashes and loses mails as soon as more than 2 or 3 mails are processed at the same time. Whether they come from an auth login or not. The worst is that we are not warned. We just see it in mail.log. Regards,
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

Have you checked your master.cf file to check the number of allowed connections for the smtp service? (first one)

<!-- gh-comment-id:1263253494 --> @tonioo commented on GitHub (Sep 30, 2022): Have you checked your master.cf file to check the number of allowed connections for the smtp service? (first one)
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

I have the default config (modboboa-installer) + the change for amavis lmtp.

smtp inet n - - - 1 postscreen

I wrote something wrong. When the system crashes, I receive a system email with the error "queue file write error" but not for all lost emails.

Objet: Postfix SMTP server: errors from sonic304-22.consmr.mail.ir2.yahoo.com[77.238.179.147]

Transcript of session follows.

Out: 220 mail.xxxxx.fr ESMTP
In:  EHLO sonic304-22.consmr.mail.ir2.yahoo.com
Out: 250-mail.xxxxx.fr
Out: 250-PIPELINING
Out: 250-SIZE 11534336
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH PLAIN LOGIN
Out: 250-AUTH=PLAIN LOGIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-DSN
Out: 250-SMTPUTF8
Out: 250 CHUNKING
In:  STARTTLS
Out: 220 2.0.0 Ready to start TLS
In:  EHLO sonic304-22.consmr.mail.ir2.yahoo.com
Out: 250-mail.xxxxxx.fr
Out: 250-PIPELINING
Out: 250-SIZE 11534336
Out: 250-ETRN
Out: 250-AUTH PLAIN LOGIN
Out: 250-AUTH=PLAIN LOGIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250-DSN
Out: 250-SMTPUTF8
Out: 250 CHUNKING
In:  MAIL FROM:<[xxxxxx@yahoo.fr](mailto:xxxxxx@yahoo.fr)>
Out: 250 2.1.0 Ok
In:  RCPT TO:<[xxxxxx@xxxxxx.org](mailto: xxxxxx@xxxxxx.org)>
Out: 250 2.1.5 Ok
In:  DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
In:  QUIT
Out: 221 2.0.0 Bye

EDIT: and this in the log.

Sep 29 15:06:22 mailhub postfix/smtpd[67769]: timeout after END-OF-MESSAGE from mx0b-002e3701.pphosted.com[148.163.143.35]
Sep 29 19:22:31 mailhub postfix/smtpd[196091]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
Sep 29 19:59:41 mailhub postfix/smtpd[210417]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]

<!-- gh-comment-id:1263269020 --> @stefaweb commented on GitHub (Sep 30, 2022): I have the default config (modboboa-installer) + the change for amavis lmtp. `smtp inet n - - - 1 postscreen` I wrote something wrong. When the system crashes, I receive a system email with the error "queue file write error" but not for all lost emails. ``` Objet: Postfix SMTP server: errors from sonic304-22.consmr.mail.ir2.yahoo.com[77.238.179.147] Transcript of session follows. Out: 220 mail.xxxxx.fr ESMTP In: EHLO sonic304-22.consmr.mail.ir2.yahoo.com Out: 250-mail.xxxxx.fr Out: 250-PIPELINING Out: 250-SIZE 11534336 Out: 250-ETRN Out: 250-STARTTLS Out: 250-AUTH PLAIN LOGIN Out: 250-AUTH=PLAIN LOGIN Out: 250-ENHANCEDSTATUSCODES Out: 250-8BITMIME Out: 250-DSN Out: 250-SMTPUTF8 Out: 250 CHUNKING In: STARTTLS Out: 220 2.0.0 Ready to start TLS In: EHLO sonic304-22.consmr.mail.ir2.yahoo.com Out: 250-mail.xxxxxx.fr Out: 250-PIPELINING Out: 250-SIZE 11534336 Out: 250-ETRN Out: 250-AUTH PLAIN LOGIN Out: 250-AUTH=PLAIN LOGIN Out: 250-ENHANCEDSTATUSCODES Out: 250-8BITMIME Out: 250-DSN Out: 250-SMTPUTF8 Out: 250 CHUNKING In: MAIL FROM:<[xxxxxx@yahoo.fr](mailto:xxxxxx@yahoo.fr)> Out: 250 2.1.0 Ok In: RCPT TO:<[xxxxxx@xxxxxx.org](mailto: xxxxxx@xxxxxx.org)> Out: 250 2.1.5 Ok In: DATA Out: 354 End data with <CR><LF>.<CR><LF> Out: 451 4.3.0 Error: queue file write error In: QUIT Out: 221 2.0.0 Bye ``` EDIT: and this in the log. ``` Sep 29 15:06:22 mailhub postfix/smtpd[67769]: timeout after END-OF-MESSAGE from mx0b-002e3701.pphosted.com[148.163.143.35] Sep 29 19:22:31 mailhub postfix/smtpd[196091]: timeout after END-OF-MESSAGE from localhost[127.0.0.1] Sep 29 19:59:41 mailhub postfix/smtpd[210417]: timeout after END-OF-MESSAGE from localhost[127.0.0.1] ```
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

And what is your base RAM consumption when everything is running?

<!-- gh-comment-id:1263285700 --> @tonioo commented on GitHub (Sep 30, 2022): And what is your base RAM consumption when everything is running?
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

I have this with the amavis lmtp config.

root@mailhub:~# free -h
               total        used        free      shared  buff/cache   available
Mem:           7.8Gi       2.0Gi       2.4Gi        23Mi       3.4Gi       5.5Gi
Swap:             0B          0B          0B

root@mailhub:~# vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 2472916 141996 3449880    0    0    17    22   79  117  4  1 94  0  0
<!-- gh-comment-id:1263291763 --> @stefaweb commented on GitHub (Sep 30, 2022): I have this with the amavis lmtp config. ``` root@mailhub:~# free -h total used free shared buff/cache available Mem: 7.8Gi 2.0Gi 2.4Gi 23Mi 3.4Gi 5.5Gi Swap: 0B 0B 0B root@mailhub:~# vmstat procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 0 2472916 141996 3449880 0 0 17 22 79 117 4 1 94 0 0 ```
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

Have you also updated the maxproc setting of the smtp-amavis service? It should be equal to $max_server

<!-- gh-comment-id:1263296263 --> @tonioo commented on GitHub (Sep 30, 2022): Have you also updated the maxproc setting of the smtp-amavis service? It should be equal to $max_server
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

Oops, I'm lost.

I will put the default settings without lmtp and I will do new tests.

<!-- gh-comment-id:1263306078 --> @stefaweb commented on GitHub (Sep 30, 2022): Oops, I'm lost. I will put the default settings without lmtp and I will do new tests.
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

Here is the consumption with the default settings just after a reboot.

I will now wait to see if the errors start again.

`
root@mailhub:~# free -h
total used free shared buff/cache available
Mem: 7.8Gi 1.8Gi 4.1Gi 21Mi 1.9Gi 5.7Gi
Swap: 0B 0B 0B

root@mailhub:~# vmstat
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 0 0 4326024 36996 1933840 0 0 3404 505 171 247 8 4 86 3 0
`

Here are the default settings after the config via modoboa-installer.

/etc/amavis/conf.d/50-user
$inet_socket_port = [9998, 10024, 10026];
$max_servers = 1;

/etc/postfix/master.cf
smtp      inet  n       -       -       -       1       postscreen
smtpd     pass  -       -       -       -       -       smtpd
  -o smtpd_proxy_filter=inet:[127.0.0.1]:10024
  -o smtpd_proxy_options=speed_adjust

Nothing added in /etc/postfix/main.cf.

<!-- gh-comment-id:1263311321 --> @stefaweb commented on GitHub (Sep 30, 2022): Here is the consumption with the default settings just after a reboot. I will now wait to see if the errors start again. ` root@mailhub:~# free -h total used free shared buff/cache available Mem: 7.8Gi 1.8Gi 4.1Gi 21Mi 1.9Gi 5.7Gi Swap: 0B 0B 0B root@mailhub:~# vmstat procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 0 0 0 4326024 36996 1933840 0 0 3404 505 171 247 8 4 86 3 0 ` Here are the default settings after the config via modoboa-installer. ``` /etc/amavis/conf.d/50-user $inet_socket_port = [9998, 10024, 10026]; $max_servers = 1; /etc/postfix/master.cf smtp inet n - - - 1 postscreen smtpd pass - - - - - smtpd -o smtpd_proxy_filter=inet:[127.0.0.1]:10024 -o smtpd_proxy_options=speed_adjust ``` Nothing added in /etc/postfix/main.cf.
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

Well, that didn't drag.

I did not receive an error mail on postmaster@.

Sep 30 11:06:41 mailhub postfix/smtpd[3547]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
<!-- gh-comment-id:1263321860 --> @stefaweb commented on GitHub (Sep 30, 2022): Well, that didn't drag. I did not receive an error mail on postmaster@. ``` Sep 30 11:06:41 mailhub postfix/smtpd[3547]: timeout after END-OF-MESSAGE from localhost[127.0.0.1] ```
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

And if you increase max_servers and max proc to 2?

<!-- gh-comment-id:1263334411 --> @tonioo commented on GitHub (Sep 30, 2022): And if you increase max_servers and max proc to 2?
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

I'm going to try.

It seems to only do this when there is more than one mail to process. If there is only one, I don't get the error.

Sep 30 11:01:35 mailhub postfix/smtpd[3547]: connect from localhost[127.0.0.1]
Sep 30 11:01:35 mailhub postfix/smtpd[3547]: 8118021112: client=localhost[127.0.0.1], orig_client=82-64-xxxx-71.subs.proxad.net[82.64.xxx.71]
Sep 30 11:01:41 mailhub postfix/smtpd[3547]: 5F8A921113: client=localhost[127.0.0.1], orig_client=listes.xxxx.fr[62.210.xxx.5]
Sep 30 11:06:41 mailhub postfix/smtpd[3547]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
Sep 30 11:06:41 mailhub postfix/smtpd[3547]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=2 mail=2 rcpt=3 data=2 commands=10

<!-- gh-comment-id:1263338063 --> @stefaweb commented on GitHub (Sep 30, 2022): I'm going to try. It seems to only do this when there is more than one mail to process. If there is only one, I don't get the error. ``` Sep 30 11:01:35 mailhub postfix/smtpd[3547]: connect from localhost[127.0.0.1] Sep 30 11:01:35 mailhub postfix/smtpd[3547]: 8118021112: client=localhost[127.0.0.1], orig_client=82-64-xxxx-71.subs.proxad.net[82.64.xxx.71] Sep 30 11:01:41 mailhub postfix/smtpd[3547]: 5F8A921113: client=localhost[127.0.0.1], orig_client=listes.xxxx.fr[62.210.xxx.5] Sep 30 11:06:41 mailhub postfix/smtpd[3547]: timeout after END-OF-MESSAGE from localhost[127.0.0.1] Sep 30 11:06:41 mailhub postfix/smtpd[3547]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=2 mail=2 rcpt=3 data=2 commands=10 ```
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

It doesn't like to set the values to 2. I put 1 back for max_servers and max proc to.

Sep 30 11:35:07 mailhub postfix/postscreen[1931]: fatal: service smtp requires a process limit of 1

<!-- gh-comment-id:1263343202 --> @stefaweb commented on GitHub (Sep 30, 2022): It doesn't like to set the values to 2. I put 1 back for max_servers and max proc to. `Sep 30 11:35:07 mailhub postfix/postscreen[1931]: fatal: service smtp requires a process limit of 1`
Author
Owner

@tonioo commented on GitHub (Sep 30, 2022):

It's smtp-amavis service that you must update, not the smtp one

<!-- gh-comment-id:1263359521 --> @tonioo commented on GitHub (Sep 30, 2022): It's smtp-amavis service that you must update, not the smtp one
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

And if we use theses commands in Amavis?

  $smtp_connection_cache_on_demand = 1;
  $smtp_connection_cache_enable = 1;

I found this old text while searching with Google.

A result of connection caching when it happens the session is held
in hope for a next task, which doesn't come soon enough.
No harm done. The feature can be disabled for low traffic sites.
- smtp client connection caching is a new feature which allows smtp client
code in amavisd to keep a SMTP session to MTA open after forwarding a
message or a notification, so that a next mail message that needs to be
sent by this child process can avoid re-establishing a session and the
initial greeting/EHLO (and TLS) handshake.

A current value of a global settings $smtp_connection_cache_enable
controls whether a session will be retained after forwarding a message
or not. Its default initial value is true.

A global setting $smtp_connection_cache_on_demand controls whether amavisd
is allowed to dynamically change the $smtp_connection_cache_enable setting
according to its estimate of the message frequency. The heuristics is
currently very simple: if time interval between a previous task completion
by this child process and the arrival of a current message is 5 seconds
or less, the $smtp_connection_cache_enable is turned on (which will affect
the next message); if the interval is 15 seconds or more, it is turned off.
The default value of the $smtp_connection_cache_on_demand is true, thus
enabling the adaptive behaviour.

On a busy server the connection caching can save some processing time.
Savings are substantial if client-side TLS is enabled, otherwise just a
few milliseconds are saved. On an idle server the feature may unnecessarily
keep sessions to MTA open (until MTA times them out), so one can disable
the feature by setting both controls to false (to 0 or undef).

To monitor the connection caching effectiveness, some SNMP-like counters
were added, so amavisd-agent may display something like:

OutConnNew 2764 319/h 98.2 % (OutMsgs)
OutConnQuit 2521 291/h 89.5 % (OutMsgs)
OutConnReuseFail 7 1/h 0.2 % (OutMsgs)
OutConnReuseRecent 21 2/h 0.7 % (OutMsgs)
OutConnReuseRefreshed 31 4/h 1.1 % (OutMsgs)
OutConnTransact 2816 325/h 100.0 % (OutMsgs)

<!-- gh-comment-id:1263359858 --> @stefaweb commented on GitHub (Sep 30, 2022): And if we use theses commands in Amavis? ``` $smtp_connection_cache_on_demand = 1; $smtp_connection_cache_enable = 1; ``` I found this old text while searching with Google. ``` A result of connection caching when it happens the session is held in hope for a next task, which doesn't come soon enough. No harm done. The feature can be disabled for low traffic sites. - smtp client connection caching is a new feature which allows smtp client code in amavisd to keep a SMTP session to MTA open after forwarding a message or a notification, so that a next mail message that needs to be sent by this child process can avoid re-establishing a session and the initial greeting/EHLO (and TLS) handshake. A current value of a global settings $smtp_connection_cache_enable controls whether a session will be retained after forwarding a message or not. Its default initial value is true. A global setting $smtp_connection_cache_on_demand controls whether amavisd is allowed to dynamically change the $smtp_connection_cache_enable setting according to its estimate of the message frequency. The heuristics is currently very simple: if time interval between a previous task completion by this child process and the arrival of a current message is 5 seconds or less, the $smtp_connection_cache_enable is turned on (which will affect the next message); if the interval is 15 seconds or more, it is turned off. The default value of the $smtp_connection_cache_on_demand is true, thus enabling the adaptive behaviour. On a busy server the connection caching can save some processing time. Savings are substantial if client-side TLS is enabled, otherwise just a few milliseconds are saved. On an idle server the feature may unnecessarily keep sessions to MTA open (until MTA times them out), so one can disable the feature by setting both controls to false (to 0 or undef). To monitor the connection caching effectiveness, some SNMP-like counters were added, so amavisd-agent may display something like: OutConnNew 2764 319/h 98.2 % (OutMsgs) OutConnQuit 2521 291/h 89.5 % (OutMsgs) OutConnReuseFail 7 1/h 0.2 % (OutMsgs) OutConnReuseRecent 21 2/h 0.7 % (OutMsgs) OutConnReuseRefreshed 31 4/h 1.1 % (OutMsgs) OutConnTransact 2816 325/h 100.0 % (OutMsgs) ```
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

It's smtp-amavis service that you must update, not the smtp one

I no longer have smtp-amavis in master.cf because I switched to the default config without the smtp-amavis lmtp service. When I use the smtp-amavis lmtp service, I no longer have these errors.

When I used the lmtp config, I had 2 for max_servers and the max proc for the smtp-amavis service.

<!-- gh-comment-id:1263365622 --> @stefaweb commented on GitHub (Sep 30, 2022): > It's smtp-amavis service that you must update, not the smtp one I no longer have smtp-amavis in master.cf because I switched to the default config without the smtp-amavis lmtp service. When I use the smtp-amavis lmtp service, I no longer have these errors. When I used the lmtp config, I had 2 for max_servers and the max proc for the smtp-amavis service.
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

And if we use theses commands in Amavis?

  $smtp_connection_cache_on_demand = 1;
  $smtp_connection_cache_enable = 1;

It still does with these settings. I removed them.

I switched back to lmtp config as long as there are no other tests to do.

<!-- gh-comment-id:1263450499 --> @stefaweb commented on GitHub (Sep 30, 2022): > And if we use theses commands in Amavis? > > ``` > $smtp_connection_cache_on_demand = 1; > $smtp_connection_cache_enable = 1; > ``` It still does with these settings. I removed them. I switched back to lmtp config as long as there are no other tests to do.
Author
Owner

@stefaweb commented on GitHub (Sep 30, 2022):

Again me.

I tried parsing the last logs with default proxy config + above two cache commands enabled.

I can't figure out if the "timeout after END-OF-MESSAGE" is an error or normal behavior with caches. The mail arrived well in the quarantine of the GUI if needed.

I did not have any other such error during this short test.

I removed the lines of the logs which are useless.

Sep 30 12:46:31 mailhub postfix/smtpd[17493]: connect from domain.org[62.210.xxx.xx]
Sep 30 12:46:32 mailhub postfix/verify[17695]: cache proxy:btree:/var/lib/postfix/verify_cache full cleanup: retained=10 dropped=0 entries
Sep 30 12:46:32 mailhub postfix/smtpd[17493]: NOQUEUE: client=domain.org[62.210.xxx.xx]
Sep 30 12:46:33 mailhub postfix/smtpd[17719]: connect from localhost[127.0.0.1]
Sep 30 12:46:33 mailhub postfix/smtpd[17719]: 4FF2221113: client=localhost[127.0.0.1], orig_client=domain.org[62.210.xxx.xx]
Sep 30 12:46:33 mailhub postfix/cleanup[17720]: 4FF2221113: message-id=<20220930104631.D88BC4C119E@cabanis.domain.org>
Sep 30 12:46:33 mailhub opendkim[1315]: 4FF2221113: no signing table match for 'MAILER-DAEMON@cabanis.domain.org'
Sep 30 12:46:33 mailhub opendkim[1315]: 4FF2221113: no signature data
Sep 30 12:46:33 mailhub postfix/qmgr[1305]: 4FF2221113: from=<>, size=4595, nrcpt=1 (queue active)
Sep 30 12:46:33 mailhub amavis[9459]: (09459-01) Passed CLEAN {RelayedInbound}, [62.210.xxx.xx]:38418 [62.210.xxx.xx] <> -> <webmaster@domain.org>, Message-ID: <20220930104631.D88BC4C119E@cabanis.domain.org>, mail_id: A13-Lh82CBo2, Hits: 0.002, size: 4117, queued_as: 4FF2221113, 1295 ms
Sep 30 12:46:33 mailhub postfix/smtpd[17493]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4FF2221113; from=<> to=<webmaster@domain.org> proto=ESMTP helo=<cabanis.domain.org>
Sep 30 12:46:33 mailhub postfix/smtpd[17493]: disconnect from domain.org[62.210.xxx.xx] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Sep 30 12:51:33 mailhub postfix/smtpd[17719]: timeout after END-OF-MESSAGE from localhost[127.0.0.1]
Sep 30 12:51:33 mailhub postfix/smtpd[17719]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5
<!-- gh-comment-id:1263470617 --> @stefaweb commented on GitHub (Sep 30, 2022): Again me. I tried parsing the last logs with default proxy config + above two cache commands enabled. I can't figure out if the "timeout after END-OF-MESSAGE" is an error or normal behavior with caches. The mail arrived well in the quarantine of the GUI if needed. I did not have any other such error during this short test. I removed the lines of the logs which are useless. ``` Sep 30 12:46:31 mailhub postfix/smtpd[17493]: connect from domain.org[62.210.xxx.xx] Sep 30 12:46:32 mailhub postfix/verify[17695]: cache proxy:btree:/var/lib/postfix/verify_cache full cleanup: retained=10 dropped=0 entries Sep 30 12:46:32 mailhub postfix/smtpd[17493]: NOQUEUE: client=domain.org[62.210.xxx.xx] Sep 30 12:46:33 mailhub postfix/smtpd[17719]: connect from localhost[127.0.0.1] Sep 30 12:46:33 mailhub postfix/smtpd[17719]: 4FF2221113: client=localhost[127.0.0.1], orig_client=domain.org[62.210.xxx.xx] Sep 30 12:46:33 mailhub postfix/cleanup[17720]: 4FF2221113: message-id=<20220930104631.D88BC4C119E@cabanis.domain.org> Sep 30 12:46:33 mailhub opendkim[1315]: 4FF2221113: no signing table match for 'MAILER-DAEMON@cabanis.domain.org' Sep 30 12:46:33 mailhub opendkim[1315]: 4FF2221113: no signature data Sep 30 12:46:33 mailhub postfix/qmgr[1305]: 4FF2221113: from=<>, size=4595, nrcpt=1 (queue active) Sep 30 12:46:33 mailhub amavis[9459]: (09459-01) Passed CLEAN {RelayedInbound}, [62.210.xxx.xx]:38418 [62.210.xxx.xx] <> -> <webmaster@domain.org>, Message-ID: <20220930104631.D88BC4C119E@cabanis.domain.org>, mail_id: A13-Lh82CBo2, Hits: 0.002, size: 4117, queued_as: 4FF2221113, 1295 ms Sep 30 12:46:33 mailhub postfix/smtpd[17493]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4FF2221113; from=<> to=<webmaster@domain.org> proto=ESMTP helo=<cabanis.domain.org> Sep 30 12:46:33 mailhub postfix/smtpd[17493]: disconnect from domain.org[62.210.xxx.xx] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 Sep 30 12:51:33 mailhub postfix/smtpd[17719]: timeout after END-OF-MESSAGE from localhost[127.0.0.1] Sep 30 12:51:33 mailhub postfix/smtpd[17719]: disconnect from localhost[127.0.0.1] ehlo=1 xforward=1 mail=1 rcpt=1 data=1 commands=5 ```
Author
Owner

@stefaweb commented on GitHub (Oct 1, 2022):

Hello,

I redid the tests with the default proxy configuration.

If I add these two commands in /etc/amavis/conf.d/50-user the problem disappears.

$smtp_connection_cache_on_demand = 1;
$smtp_connection_cache_enable = 1;

Nothing else to change.

I'm going to let it run for several days to be sure.

<!-- gh-comment-id:1264275661 --> @stefaweb commented on GitHub (Oct 1, 2022): Hello, I redid the tests with the default proxy configuration. If I add these two commands in /etc/amavis/conf.d/50-user the problem disappears. ``` $smtp_connection_cache_on_demand = 1; $smtp_connection_cache_enable = 1; ``` Nothing else to change. I'm going to let it run for several days to be sure.
Author
Owner

@stefaweb commented on GitHub (Oct 3, 2022):

Hello,

Well, that does it again twice at short intervals.

I now have amavis logging enabled for next error and waited again.

If I understand the problem correctly. A first processing of several emails is executed. At the end of this processing, an error "DB unregistering failed" occurs and the amavis process crashes.

Oct  1 10:14:19 mailhub amavis[669]: (00669-17) Passed CLEAN {RelayedOutbound}, ORIGINATING LOCAL [82.xxx.xxx.71]:61861 [82.xxx.xxx.71] <user1@domain.org> -> <group@liste.domain.org>, Message-ID: <367A91AE-3AA3-468C-86D3-4F07FE735105@domain.org>, mail_id: KkXOiLOcopeC, Hits: -0.998, size: 8906, queued_as: 46FB52110B, 1362 ms
Oct  1 10:14:26 mailhub amavis[669]: (00669-18) Passed CLEAN {RelayedInbound}, [62.xxx.xxx.5]:47224 [82.xxx.xxx.71] <group-bounces@liste.domain.org> -> <user2@domain.org>,<user1@domain.org>, Message-ID: <367A91AE-3AA3-468C-86D3-4F07FE735105@domain.org>, mail_id: u1VpQuYWRWhe, Hits: -1.097, size: 14109, queued_as: D436021113, 2330 ms
Oct  1 12:18:01 mailhub CRON[652277]: (amavis) CMD (test -e /usr/sbin/amavisd-new-cronjob && /usr/sbin/amavisd-new-cronjob sa-sync)
Oct  1 13:00:23 mailhub amavis[669]: (00669-19) Passed CLEAN {RelayedInbound}, [209.85.219.197]:33342 [209.85.219.197] <3xB04YxQKAwEhpphmfbmfsut-opsfqmzhpphmf.dpni3pdzcfslbub.psh@alerts.bounces.google.com> -> <user2@domain.org>, Message-ID: <00000000000030a88005e9f704c7@google.com>, mail_id: 2x-5f1SkCM6v, Hits: -9.699, size: 17000, queued_as: A95D421113, 1431 ms
Oct  1 13:00:28 mailhub amavis[669]: (00669-20) Passed CLEAN {RelayedInbound}, [209.85.219.197]:41881 [209.85.219.197] <3yR04YxQKAwYmuumrkgrkxzy-tuxkvr4muumrk.iusn8ui4hkxqgzg.uxm@alerts.bounces.google.com> -> <user2@domain.org>, Message-ID: <000000000000858b9d05e9f704ea@google.com>, mail_id: dEAIYvnTdXkY, Hits: -9.699, size: 14382, queued_as: 9736221114, 1924 ms
Oct  1 13:00:28 mailhub amavis[669]: (00669-20) (!)Amavis::END: DB unregistering failed:
Oct  1 13:00:28 mailhub systemd[1]: amavis.service: Succeeded.
Oct  1 13:00:28 mailhub systemd[1]: amavis.service: Consumed 6.053s CPU time.

Another email arrives a little later and the processing crashes because the amavis proxy is no longer available.

Oct  1 13:02:57 mailhub postfix/postscreen[671426]: CONNECT from [209.85.219.200]:51807 to [10.194.192.21]:25
Oct  1 13:02:57 mailhub postfix/postscreen[671426]: WHITELISTED [209.85.219.200]:51807
Oct  1 13:02:57 mailhub postfix/smtpd[670727]: connect from mail-yb1-f200.google.com[209.85.219.200]
Oct  1 13:02:58 mailhub postfix/smtpd[670727]: Anonymous TLS connection established from mail-yb1-f200.google.com[209.85.219.200]: TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange ECDHE (P-256) server-signature RSA-PSS (2048 bits) server-digest SHA256
Oct  1 13:02:58 mailhub postfix/smtpd[670727]: NOQUEUE: client=mail-yb1-f200.google.com[209.85.219.200]
Oct  1 13:02:58 mailhub postfix/smtpd[670727]: warning: connect to proxy filter inet:[127.0.0.1]:10024: Connection refused
Oct  1 13:02:58 mailhub postfix/smtpd[670727]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<3YR44YxQKA54EMMEJC8JCPRQ-LMPCNJWEMMEJC.AMKFaMAW9CPI8R8.MPE@alerts.bounces.google.com> to=<user2@domain.org> proto=ESMTP helo=<mail-yb1-f200.google.com>

Something weird with the amavis process it seems.

If I look with a systemlctl status amavis.

If we have $max_servers = 1;

      CGroup: /system.slice/amavis.service
              └─702515 /usr/sbin/amavisd-new (master)

If we have $max_servers = 2;

     CGroup: /system.slice/amavis.service
             ├─702632 /usr/sbin/amavisd-new (master)
             ├─702645 /usr/sbin/amavisd-new (virgin child)
             └─702646 /usr/sbin/amavisd-new (virgin child)

When we set max_servers to 1, we have no child.

So, with $max_servers = 1 if the process crashes, it's the master process that crashes and we lose the amavis proxy.

The minimum value for max_servers should therefore be = 2 to be sure that amavis will be still alive if a process crash.

On the other hand, I still don't understand why the amavis child crashes with a "DB unregistering failed" under certain conditions. It hasn't done it again since Saturday.

Regards,

<!-- gh-comment-id:1265579533 --> @stefaweb commented on GitHub (Oct 3, 2022): Hello, Well, that does it again twice at short intervals. I now have amavis logging enabled for next error and waited again. If I understand the problem correctly. A first processing of several emails is executed. At the end of this processing, an error "DB unregistering failed" occurs and the amavis process crashes. ``` Oct 1 10:14:19 mailhub amavis[669]: (00669-17) Passed CLEAN {RelayedOutbound}, ORIGINATING LOCAL [82.xxx.xxx.71]:61861 [82.xxx.xxx.71] <user1@domain.org> -> <group@liste.domain.org>, Message-ID: <367A91AE-3AA3-468C-86D3-4F07FE735105@domain.org>, mail_id: KkXOiLOcopeC, Hits: -0.998, size: 8906, queued_as: 46FB52110B, 1362 ms Oct 1 10:14:26 mailhub amavis[669]: (00669-18) Passed CLEAN {RelayedInbound}, [62.xxx.xxx.5]:47224 [82.xxx.xxx.71] <group-bounces@liste.domain.org> -> <user2@domain.org>,<user1@domain.org>, Message-ID: <367A91AE-3AA3-468C-86D3-4F07FE735105@domain.org>, mail_id: u1VpQuYWRWhe, Hits: -1.097, size: 14109, queued_as: D436021113, 2330 ms Oct 1 12:18:01 mailhub CRON[652277]: (amavis) CMD (test -e /usr/sbin/amavisd-new-cronjob && /usr/sbin/amavisd-new-cronjob sa-sync) Oct 1 13:00:23 mailhub amavis[669]: (00669-19) Passed CLEAN {RelayedInbound}, [209.85.219.197]:33342 [209.85.219.197] <3xB04YxQKAwEhpphmfbmfsut-opsfqmzhpphmf.dpni3pdzcfslbub.psh@alerts.bounces.google.com> -> <user2@domain.org>, Message-ID: <00000000000030a88005e9f704c7@google.com>, mail_id: 2x-5f1SkCM6v, Hits: -9.699, size: 17000, queued_as: A95D421113, 1431 ms Oct 1 13:00:28 mailhub amavis[669]: (00669-20) Passed CLEAN {RelayedInbound}, [209.85.219.197]:41881 [209.85.219.197] <3yR04YxQKAwYmuumrkgrkxzy-tuxkvr4muumrk.iusn8ui4hkxqgzg.uxm@alerts.bounces.google.com> -> <user2@domain.org>, Message-ID: <000000000000858b9d05e9f704ea@google.com>, mail_id: dEAIYvnTdXkY, Hits: -9.699, size: 14382, queued_as: 9736221114, 1924 ms Oct 1 13:00:28 mailhub amavis[669]: (00669-20) (!)Amavis::END: DB unregistering failed: Oct 1 13:00:28 mailhub systemd[1]: amavis.service: Succeeded. Oct 1 13:00:28 mailhub systemd[1]: amavis.service: Consumed 6.053s CPU time. ``` Another email arrives a little later and the processing crashes because the amavis proxy is no longer available. ``` Oct 1 13:02:57 mailhub postfix/postscreen[671426]: CONNECT from [209.85.219.200]:51807 to [10.194.192.21]:25 Oct 1 13:02:57 mailhub postfix/postscreen[671426]: WHITELISTED [209.85.219.200]:51807 Oct 1 13:02:57 mailhub postfix/smtpd[670727]: connect from mail-yb1-f200.google.com[209.85.219.200] Oct 1 13:02:58 mailhub postfix/smtpd[670727]: Anonymous TLS connection established from mail-yb1-f200.google.com[209.85.219.200]: TLSv1.3 with cipher TLS_AES_128_GCM_SHA256 (128/128 bits) key-exchange ECDHE (P-256) server-signature RSA-PSS (2048 bits) server-digest SHA256 Oct 1 13:02:58 mailhub postfix/smtpd[670727]: NOQUEUE: client=mail-yb1-f200.google.com[209.85.219.200] Oct 1 13:02:58 mailhub postfix/smtpd[670727]: warning: connect to proxy filter inet:[127.0.0.1]:10024: Connection refused Oct 1 13:02:58 mailhub postfix/smtpd[670727]: proxy-reject: END-OF-MESSAGE: 451 4.3.0 Error: queue file write error; from=<3YR44YxQKA54EMMEJC8JCPRQ-LMPCNJWEMMEJC.AMKFaMAW9CPI8R8.MPE@alerts.bounces.google.com> to=<user2@domain.org> proto=ESMTP helo=<mail-yb1-f200.google.com> ``` Something weird with the amavis process it seems. If I look with a systemlctl status amavis. If we have $max_servers = 1; ``` CGroup: /system.slice/amavis.service └─702515 /usr/sbin/amavisd-new (master) ``` If we have $max_servers = 2; ``` CGroup: /system.slice/amavis.service ├─702632 /usr/sbin/amavisd-new (master) ├─702645 /usr/sbin/amavisd-new (virgin child) └─702646 /usr/sbin/amavisd-new (virgin child) ``` When we set max_servers to 1, we have no child. So, with $max_servers = 1 if the process crashes, it's the master process that crashes and we lose the amavis proxy. The minimum value for max_servers should therefore be = 2 to be sure that amavis will be still alive if a process crash. On the other hand, I still don't understand why the amavis child crashes with a "DB unregistering failed" under certain conditions. It hasn't done it again since Saturday. Regards,
Author
Owner

@Spitfireap commented on GitHub (Oct 3, 2022):

It's probably because of max_use, with amavis it should default to 20 (https://amavis.org/README.postfix.html#basics_transport_lmtp-client) and it marks the number of precessing before terminating the instance (probably for memory management I guess). So if $max_servers is set to 1, then the master process gets terminated: amavis won't restart.

<!-- gh-comment-id:1265601958 --> @Spitfireap commented on GitHub (Oct 3, 2022): It's probably because of `max_use`, with amavis it should default to 20 (https://amavis.org/README.postfix.html#basics_transport_lmtp-client) and it marks the number of precessing before terminating the instance (probably for memory management I guess). So if `$max_servers` is set to 1, then the master process gets terminated: amavis won't restart.
Author
Owner

@stefaweb commented on GitHub (Oct 3, 2022):

To clarify, I 'm now using fresh default install for amavis, not the lmtp version as described in https://github.com/modoboa/modoboa-installer/pull/425.

Changes to default:

In /etc/amavis/conf.d/50-user

$max_servers = 2;
$smtp_connection_cache_on_demand = 1;
$smtp_connection_cache_enable = 1;

Since Saturday no more crash yet with this (DB unregistering or queue file write error).

<!-- gh-comment-id:1265618652 --> @stefaweb commented on GitHub (Oct 3, 2022): To clarify, I 'm now using fresh default install for amavis, not the lmtp version as described in https://github.com/modoboa/modoboa-installer/pull/425. Changes to default: ``` In /etc/amavis/conf.d/50-user $max_servers = 2; $smtp_connection_cache_on_demand = 1; $smtp_connection_cache_enable = 1; ``` Since Saturday no more crash yet with this (DB unregistering or queue file write error).
Author
Owner

@fedi-will commented on GitHub (Oct 13, 2022):

Same problem here.
Yesterday I installed modoboa, everything working fine.

Now I wanted to test the issue at hand here:
I manually sent like 25 emails from an external account to my modoboa test account. (plain text, no attachment, "manually" sent one after the other from Thunderbird, took me several minutes, so no "burst" occurred)

Result

  1. I have only 17 mails in my test account's inbox.
  2. /var/log/mail.warn says:
Oct 13 19:51:01 localhost amavis[18014]: (18014-23) (!)Amavis::END: DB unregistering failed:
Oct 13 19:51:02 localhost postfix/smtpd[549480]: warning: connect to proxy filter inet:[127.0.0.1]:10024: Connection refused
  1. service amavis status says:
    Active: inactive (dead) since Thu 2022-10-13 19:51:05 CEST; 26min ago
    and
Okt 13 19:51:01 amavis[18014]: (18014-23) (!)Amavis::END: DB unregistering failed:
Okt 13 19:51:05 systemd[1]: amavis.service: Succeeded.
Okt 13 19:51:05 systemd[1]: amavis.service: Consumed 7.885s CPU time.

Question

If I put $max_servers = 2; into amavis config, then could someone please tell what exactly I have to put into postfix config, so that the values match??
There have been several suggestions about that. And my /etc/postfix/master.cf has no amavis-smtp... line in it.
@stefaweb when you say in your last comment you made those changes in amavis config, did you also change/edit anything in postfix config??

About the amavis service

When this error occurs, amavis actually exits with a success status.
And as on my Debian 11 the amavis service file has Restart=on-failure, amavis isn't even restarted. That's why @vingeni's workaround from above works at least.
Exiting with success feels wrong here, right? Who is to blame for that?

<!-- gh-comment-id:1278035862 --> @fedi-will commented on GitHub (Oct 13, 2022): Same problem here. Yesterday I installed modoboa, everything working fine. Now I wanted to test the issue at hand here: I manually sent like 25 emails from an external account to my modoboa test account. (plain text, no attachment, "manually" sent one after the other from Thunderbird, took me several minutes, so no "burst" occurred) ### Result 1) I have only 17 mails in my test account's inbox. 2) /var/log/mail.warn says: ``` Oct 13 19:51:01 localhost amavis[18014]: (18014-23) (!)Amavis::END: DB unregistering failed: Oct 13 19:51:02 localhost postfix/smtpd[549480]: warning: connect to proxy filter inet:[127.0.0.1]:10024: Connection refused ``` 3) service amavis status says: ` Active: inactive (dead) since Thu 2022-10-13 19:51:05 CEST; 26min ago` and ``` Okt 13 19:51:01 amavis[18014]: (18014-23) (!)Amavis::END: DB unregistering failed: Okt 13 19:51:05 systemd[1]: amavis.service: Succeeded. Okt 13 19:51:05 systemd[1]: amavis.service: Consumed 7.885s CPU time. ``` ### Question If I put `$max_servers = 2;` into amavis config, then could someone please tell what exactly I have to put into postfix config, so that the values match?? There have been several suggestions about that. And my /etc/postfix/master.cf has no amavis-smtp... line in it. @stefaweb when you say in [your last comment](https://github.com/modoboa/modoboa/issues/2475#issuecomment-1265618652) you made those changes in amavis config, did you also change/edit anything in postfix config?? ### About the amavis service When this error occurs, amavis actually exits with a success status. And as on my Debian 11 the amavis service file has `Restart=on-failure`, amavis isn't even restarted. That's why @vingeni's workaround from above works at least. Exiting with success feels wrong here, right? Who is to blame for that?
Author
Owner

@fedi-will commented on GitHub (Oct 15, 2022):

Ok, I did the following:

  1. Made changes @stefaweb suggested above in /etc/amavis/conf.d/50-user:

$max_servers = 2;
$smtp_connection_cache_on_demand = 1;
$smtp_connection_cache_enable = 1;

  1. Applied the changes from @Spitfireap's PR to my running system:
    edited /etc/postfix/main.cf and /etc/postfix/master.cf to have amavis running as a dedicated lmtp.
    This way I can set the maxproc value to 2 so that it matches the amavis value

Test

Again manually sent 25 mails, within about 1 minute, like in my previous post.

Result

All mails were received.
No errors in the logs.

I am going to keep this configuration.

@tonioo: is a failing amavis a common occurrence or only happens to the very few people from this issue?
Having set max_servers=1 in amavis config, for how big a load is your modoboa standard installation conceptionated? Could it take a load of 100 mails per day? 1000 or 10000?

<!-- gh-comment-id:1279705991 --> @fedi-will commented on GitHub (Oct 15, 2022): Ok, I did the following: 1. Made changes @stefaweb suggested above in /etc/amavis/conf.d/50-user: > $max_servers = 2; > $smtp_connection_cache_on_demand = 1; > $smtp_connection_cache_enable = 1; 2. Applied the changes from @Spitfireap's [PR](https://github.com/modoboa/modoboa-installer/pull/425) to my running system: edited /etc/postfix/main.cf and /etc/postfix/master.cf to have amavis running as a dedicated lmtp. This way I can set the maxproc value to 2 so that it matches the amavis value ### Test Again manually sent 25 mails, within about 1 minute, like in my previous post. ### Result All mails were received. No errors in the logs. I am going to keep this configuration. @tonioo: is a failing amavis a common occurrence or only happens to the very few people from this issue? Having set max_servers=1 in amavis config, for how big a load is your modoboa standard installation conceptionated? Could it take a load of 100 mails per day? 1000 or 10000?
Author
Owner

@isaaclepes commented on GitHub (Oct 25, 2022):

Just encountered this issue after updating to latest Modoboa.
Applied the recommended changes and will see how it goes.

<!-- gh-comment-id:1290860026 --> @isaaclepes commented on GitHub (Oct 25, 2022): Just encountered this issue after updating to latest Modoboa. Applied the recommended changes and will see how it goes.
Author
Owner

@Spitfireap commented on GitHub (Oct 25, 2022):

A fix has just been pushed to the installer so the default $max_servers value is 2. Hopefully it will fix future issues :)

<!-- gh-comment-id:1290927134 --> @Spitfireap commented on GitHub (Oct 25, 2022): A fix has just been pushed to the installer so the default ``$max_servers`` value is 2. Hopefully it will fix future issues :)
Author
Owner

@isaaclepes commented on GitHub (Oct 26, 2022):

Awesome!

Just to report-back.. not only does it stop the crashing, it seems like emails are going through a bit quicker too. That could just be my imagination, though.

<!-- gh-comment-id:1291367201 --> @isaaclepes commented on GitHub (Oct 26, 2022): Awesome! Just to report-back.. not only does it stop the crashing, it seems like emails are going through a bit quicker too. That could just be my imagination, though.
Author
Owner

@stale[bot] commented on GitHub (Dec 26, 2022):

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

<!-- gh-comment-id:1364824629 --> @stale[bot] commented on GitHub (Dec 26, 2022): This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.
Author
Owner

@PatTheMav commented on GitHub (Jan 3, 2023):

For posterity's sake: The reason why $max_servers set to 1 became an issue is because of how amavis' Debian package is set up:

Systemd starts the service via ExecStart=/usr/sbin/amavisd-new foreground, which implicitly makes the service set daemonize to 0 and with only 1 server configured amavis will not fork but handle everything "in process" until the maximum amount of requests is reached and then quit.

Running with just 1 child process (which is forked anew after maximum amount of mails have been processed) requires the service to be run as a daemon, which Debian's service configuration does not do by default.

<!-- gh-comment-id:1369924417 --> @PatTheMav commented on GitHub (Jan 3, 2023): For posterity's sake: The reason why `$max_servers` set to `1` became an issue is because of how `amavis`' Debian package is set up: Systemd starts the service via `ExecStart=/usr/sbin/amavisd-new foreground`, which implicitly makes the service set `daemonize` to `0` and with only 1 server configured `amavis` will not fork but handle everything "in process" until the maximum amount of requests is reached and then quit. Running with just 1 child process (which is forked anew after maximum amount of mails have been processed) requires the service to be run as a daemon, which Debian's service configuration does not do by default.
Author
Owner

@michaelNGV commented on GitHub (Feb 16, 2023):

The identifier is $max_servers in the plural. If you're going to comment, please check what you're writing, as others will rely on it.
I did have more rant but I'll leave it there.

<!-- gh-comment-id:1432259165 --> @michaelNGV commented on GitHub (Feb 16, 2023): The identifier is `$max_servers` in the plural. If you're going to comment, please check what you're writing, as others will rely on it. I did have more rant but I'll leave it there.
Author
Owner

@isaaclepes commented on GitHub (Sep 2, 2024):

Just encountered the same issue. Can we get a note added to the Wiki for installation/upgrades that warns of this?

<!-- gh-comment-id:2323557583 --> @isaaclepes commented on GitHub (Sep 2, 2024): Just encountered the same issue. Can we get a note added to the Wiki for installation/upgrades that warns of this?
Sign in to join this conversation.
No milestone
No project
No assignees
1 participant
Notifications
Due date
The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference
starred/modoboa-modoboa#1611
No description provided.