1 Topic by Todd1561

  • Todd1561
  • Member
  • Offline
  • Registered: 2023-01-07
  • Posts: 16

Topic: amavis crashing consistently

==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.6.4 MARIADB edition
- Deployed with iRedMail Easy or the downloadable installer? downloadable
- Linux/BSD distribution name and version: Debian 12.1
- Store mail accounts in which backend (LDAP/MySQL/PGSQL):  mariadb
- Web server (Apache or Nginx): nginx
- Manage mail accounts with iRedAdmin-Pro? no
- [IMPORTANT] Related original log or error message is required if you're experiencing an issue.
====

Brand new installs of iRedMail on 2 fresh Debian 12.1 servers.  Amavis keeps crashing at least twice a day.  There's not much to go on in the logs other than the below in /var/log/syslog (this is with amavis debug logging enabled).  Doesn't seem to be a memory issue.  I started with 4GB of RAM and bumped to 5GB.  I even started logging free memory and it's always around 1GB free before, during and after the amavis issue.  Currently, I have a cron job checking and restarting the service as needed, but I'd like a more permanent fix.  Any idea what's going on?  This never happened in my previous installation on Debian 11.

2023-08-23T18:10:06.637159-04:00 mail1 amavis[1112972]: (1112972-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230823T130549-1112972-ciDAbaKY/parts, excl=1
2023-08-23T18:10:06.637186-04:00 mail1 postfix/cleanup[1141579]: 4RWL4G4WM3z95fJs: message-id=<4RWL4G0T4tz95fJK@mail1.example.net>
2023-08-23T18:10:06.637222-04:00 mail1 postfix/qmgr[2350]: 4RWL4G0T4tz95fJK: removed
2023-08-23T18:10:06.637487-04:00 mail1 amavis[1112972]: (1112972-20) size: 1545, TIMING [total 519 ms] - SMTP greeting: 0.9 (0%)0, SMTP EHLO: 0.4 (0%)0, SMTP pre-MAIL: 0.4 (0%)0, SMTP MAIL: 0.5 (0%)0, lookup_sql: 1.2 (0%)1, SMTP pre-DATA-flush: 0.5 (0%)1, SMTP DATA: 42 (8%)9, check_init: 0.1 (0%)9, digest_hdr: 0.4 (0%)9, digest_body_dkim: 0.2 (0%)9, collect_info: 0.6 (0%)9, gen_mail_id: 6 (1%)10, mime_decode: 2.5 (0%)11, get-file-type1: 5 (1%)12, parts_decode: 0.1 (0%)12, check_header: 0.4 (0%)12, lookup_sql: 1.5 (0%)12, spam-wb-list: 0.6 (0%)12, SA msg read: 0.3 (0%)12, SA parse: 1.0 (0%)12, SA check: 421 (81%)93, decide_mail_destiny: 2.2 (0%)94, notif-quar: 0.1 (0%)94, write-header: 2.5 (0%)94, fwd-data-dkim: 2.8 (1%)95, fwd-connect: 9 (2%)97, fwd-mail-pip: 5 (1%)98, fwd-rcpt-pip: 0.1 (0%)98, fwd-data-chkpnt: 0.0 (0%)98, write-header: 0.2 (0%)98, fwd-data-contents: 0.0 (0%)98, fwd-end-chkpnt: 4.8 (1%)99, prepare-dsn: 0.5 (0%)99, report: 0.6 (0%)99, main_log_entry: 3.3 (1%)99, sql-update: 2.4 (0%)100, SMTP pre-respon...
2023-08-23T18:10:06.637542-04:00 mail1 amavis[1112972]: (1112972-20) ...se: 0.1 (0%)100, SMTP response: 0.1 (0%)100, unlink-1-files: 0.1 (0%)100, rundown: 0.3 (0%)100
2023-08-23T18:10:06.637575-04:00 mail1 amavis[1112972]: (1112972-20) idle_proc, 6: was busy, 515.9 ms, total idle 18248.513 s, busy 8.168 s
2023-08-23T18:10:06.637603-04:00 mail1 amavis[1112972]: (1112972-20) idle_proc, 5: was idle, 0.0 ms, total idle 18248.513 s, busy 8.168 s
2023-08-23T18:10:06.637633-04:00 mail1 amavis[1112972]: (1112972-20) ESMTP< QUIT\r\n
2023-08-23T18:10:06.637663-04:00 mail1 amavis[1112972]: (1112972-20) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
2023-08-23T18:10:06.637693-04:00 mail1 amavis[1112972]: (1112972-20) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
2023-08-23T18:10:06.637722-04:00 mail1 amavis[1112972]: (1112972-20) ESMTP> 221 2.0.0 [127.0.0.1] amavis closing transmission channel
2023-08-23T18:10:06.637750-04:00 mail1 amavis[1112972]: (1112972-20) switch_to_client_time 480 s, smtp response sent
2023-08-23T18:10:06.637775-04:00 mail1 amavis[1112972]: (1112972-20) SMTP session over, timer stopped
2023-08-23T18:10:06.637803-04:00 mail1 amavis[1112972]: (1112972-20) Requesting process rundown after 20 tasks (and 20 sessions)
2023-08-23T18:10:06.637835-04:00 mail1 amavis[1112972]: (1112972-20) TempDir::DESTROY called
2023-08-23T18:10:06.637864-04:00 mail1 amavis[1112972]: (1112972-20) TempDir removal: empty tempdir is being removed: /var/lib/amavis/tmp/amavis-20230823T130549-1112972-ciDAbaKY
2023-08-23T18:10:06.637892-04:00 mail1 amavis[1112972]: (1112972-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230823T130549-1112972-ciDAbaKY, excl=
2023-08-23T18:10:06.638009-04:00 mail1 amavis[1112972]: (1112972-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230823T130549-1112972-ciDAbaKY/parts, excl=
2023-08-23T18:10:06.638345-04:00 mail1 amavis[1112972]: (1112972-20) exiting process_request
2023-08-23T18:10:06.638387-04:00 mail1 amavis[1112972]: (1112972-20) idle_proc, bye: was busy, 0.8 ms, total idle 18248.513 s, busy 8.169 s
2023-08-23T18:10:06.638415-04:00 mail1 amavis[1112972]: (1112972-20) load: 0 %, total idle 18248.513 s, busy 8.169 s
2023-08-23T18:10:06.638472-04:00 mail1 amavis[1112972]: (1112972-20) sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
2023-08-23T18:10:06.638504-04:00 mail1 amavis[1112972]: (1112972-20) Net::Server: 2023/08/23-18:10:06 Server closing!
2023-08-23T18:10:06.638532-04:00 mail1 amavis[1112972]: (1112972-20) sd_notify (no socket): STATUS=Child processes have been stopped.
2023-08-23T18:10:06.642286-04:00 mail1 postfix/local[1141584]: 4RWL4G4QwKz95fHf: to=<root@mail1.example.net>, relay=local, delay=0.02, delays=0.01/0.01/0/0.01, dsn=2.0.0, status=sent (forwarded as 4RWL4G4WM3z95fJs)
2023-08-23T18:10:06.642355-04:00 mail1 postfix/qmgr[2350]: 4RWL4G4WM3z95fJs: from=<root@mail1.example.net>, size=3164, nrcpt=1 (queue active)
2023-08-23T18:10:06.642761-04:00 mail1 amavis[1112972]: (1112972-20) Amavis::Out::SQL::Log DESTROY called
2023-08-23T18:10:06.642800-04:00 mail1 amavis[1112972]: (1112972-20) Amavis::Lookup::SQL DESTROY called
2023-08-23T18:10:06.643789-04:00 mail1 postfix/qmgr[2350]: 4RWL4G4QwKz95fHf: removed
2023-08-23T18:10:06.644677-04:00 mail1 amavis[1112972]: (1112972-20) Amavis::Out::SQL::Connection DESTROY called
2023-08-23T18:10:06.665846-04:00 mail1 amavis[1112972]: (1112972-20) Amavis::Lookup::SQL DESTROY called
2023-08-23T18:10:06.679142-04:00 mail1 postfix/qmgr[2350]: 4RWL4G4WM3z95fJs: removed
2023-08-23T18:10:06.693415-04:00 mail1 systemd[1]: amavis.service: Deactivated successfully.
2023-08-23T18:10:06.693501-04:00 mail1 systemd[1]: amavis.service: Consumed 4.208s CPU time.

Thanks!

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,127

Re: amavis crashing consistently

- What does "crashing" mean here? Stopped automatically?
- Is clamav-daemon service running?
- Did you change any config files after iRedMail installation?

3 Reply by Todd1561 (edited by Todd1561 2023-08-24 11:17:43)

  • Todd1561
  • Member
  • Offline
  • Registered: 2023-01-07
  • Posts: 16

Re: amavis crashing consistently

Yes the amavisd service is just stopped and needs to be manually restarted.  I have clamav disabled due to it being so memory intensive (that's the way I had my old iRedMail installation on Debian 11 set up as well). I used your instructions here: https://docs.iredmail.org/completely.di … assin.html

And yes, I do have several tweaks, but I don't think anything that would cause amavis to crash.  e.g. I've lowered the spam threshold, disabled greylisting, increased the message size limit, set up a SMTP smarthost (smtp2go), and followed your instructions for letsencrypt.

Full disclosure, I do have these 2 hosts setup with multi-master MariaDB replication like what's outlined in your guide here: https://docs.iredmail.org/haproxy.keepa … terfs.html I know this is not a normal configuration, but I don't think that's related to the issue.  Even though it's multi-master I'm only ever using 1 server at a time and this is a very low volume environment (2 users).  There seems to be plenty of reports of amavis randomly stopping from the research I've done.  Most issues seem to come down to memory but I don't think that's a factor here.

Thanks!

4 Reply by ZhangHuangbin

  • ZhangHuangbin
  • ZhangHuangbin
  • iRedMail Developers
  • Offline
  • Registered: 2009-05-06
  • Posts: 31,127

Re: amavis crashing consistently

Most reported issues were caused due to lack of memory for ClamAV service, then clamav-daemon stops and so does amavis.

But you don't have clamav, i don't understand why amavis stopped. sad

5 Reply by Todd1561

  • Todd1561
  • Member
  • Offline
  • Registered: 2023-01-07
  • Posts: 16

Re: amavis crashing consistently

Thanks for looking into it.  I never found a real solution either, so I just implemented the 'fix' proposed here: https://forum.iredmail.org/topic19129-s … opped.html

The service is still stopping for some reason but it's now immediately restarting rather than waiting for my every 10 minute cron job.