Topic: Amavis dies
==== REQUIRED BASIC INFO OF YOUR IREDMAIL SERVER ====
- iRedMail version (check /etc/iredmail-release): 1.6.2 MARIADB
- Deployed with iRedMail Easy or the downloadable installer? Downloadable installer
- Linux/BSD distribution name and version: Debian 11 5.10.0-21-cloud-amd64
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- 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.
====
amavis process dies after maximum 1-2 hours of running.
syslog:
Mar 28 03:30:04 mail amavis[3049]: (03049-20) one_response_for_all <root@mail.mydomain.com>: success, r=0,b=0,d=0, ndn_needed=0, '250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4PlwDD2VtYz24LM'
Mar 28 03:30:04 mail amavis[3049]: (03049-20) notif=N, suppressed=0, ndn_needed=0, exit=0, 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4PlwDD2VtYz24LM
Mar 28 03:30:04 mail amavis[3049]: (03049-20) get_deadline delivery-notification - deadline in 479.7 s, set to 288.000 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) prolong_timer delivery-notification: timer 288, was 288, deadline in 479.7 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInternal,RelayedUntaggedOriginating}
Mar 28 03:30:04 mail amavis[3049]: (03049-20) get_deadline snmp-counters - deadline in 479.7 s, set to 288.000 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) prolong_timer snmp-counters: timer 288, was 288, deadline in 479.7 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) orcpt_encode rfc822, root@mail.mydomain.com, smtputf8
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Passed CLEAN {RelayedInternal}, ORIGINATING LOCAL [127.0.0.1] /ESMTP <root@mail.mydomain.com> -> <root@mail.mydomain.com>, (), Message-ID: <4PlwDC6tNtz24LN@mail.linuxsquare.si
te>, mail_id: sYd14royALGe, b: u8pKo5db3, Hits: 0, size: 1347, queued_as: 4PlwDD2VtYz24LM, Subject: "Cron <root@mail> /bin/bash /var/vmail/backup/backup_mysql.sh", From: <root@mail.mydomain.com>, helo=, Tests: [NO_RELAYS=-0.0
01,TVD_SPACE_RATIO=0.001], autolearn=ham autolearn_force=no, autolearnscore=0.001, dkim_new=dkim:mydomain.com, 402 ms
Mar 28 03:30:04 mail amavis[3049]: (03049-20) get_deadline main_log_entry - deadline in 479.6 s, set to 288.000 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) prolong_timer main_log_entry: timer 288, was 288, deadline in 479.6 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sql begin transaction
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sql: executing clause (12 args): INSERT INTO msgrcpt (partition_tag, mail_id, rseqnum, rid, is_local, content, ds, rs, bl, wl, bspam_level, smtp_resp) VALUES (?,?,?,?,?,?,?,?,?,?,?,?)
Mar 28 03:30:04 mail amavis[3049]: (03049-20) save_info_final sYd14royALGe, orig=Y, chks=VSHB, cont.ty=C, q.type= , q.to=, dsn=N, score=0, Message-ID: <4PlwDC6tNtz24LN@mail.mydomain.com>, From: 'root@mail.mydomain.com (Cr
on Daemon)', Subject: 'Cron <root@mail> /bin/bash /var/vmail/backup/backup_mysql.sh'
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sql: executing clause (12 args): UPDATE msgs SET content=?, quar_type=?, quar_loc=?, dsn_sent=?, spam_level=?, message_id=?, from_addr=?, subject=?, client_addr=?, originating=? WHERE
partition_tag=? AND mail_id=?
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sql commit
Mar 28 03:30:04 mail amavis[3049]: (03049-20) TIMING-SA total 138 ms - parse: 1.22 (0.9%), extract_message_metadata: 8 (5.7%), get_uri_detail_list: 0.91 (0.7%), tests_pri_-2000: 4.1 (2.9%), tests_pri_-1000: 1.54 (1.1%), tests_pri
_-950: 1.33 (1.0%), tests_pri_-900: 0.82 (0.6%), tests_pri_-90: 0.89 (0.6%), tests_pri_0: 74 (53.5%), check_spf: 0.50 (0.4%), check_dkim_adsp: 13 (9.2%), tests_pri_20: 1.14 (0.8%), tests_pri_30: 1.70 (1.2%), check_pyzor: 0.20 (0.
1%), tests_pri_500: 10 (7.1%), poll_dns_idle: 3.6 (2.6%), learn: 22 (16.1%), b_learn: 20 (14.5%), b_count_change: 2.3 (1.7%), get_report: 0.24 (0.2%)
Mar 28 03:30:04 mail amavis[3049]: (03049-20) get_deadline check done - deadline in 479.6 s, set to 288.000 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) prolong_timer check done: timer 288, was 288, deadline in 479.6 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4PlwDD2VtYz24LM"
Mar 28 03:30:04 mail amavis[3049]: (03049-20) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4PlwDD2VtYz24LM
Mar 28 03:30:04 mail amavis[3049]: (03049-20) switch_to_client_time 480 s, smtp response sent
Mar 28 03:30:04 mail amavis[3049]: (03049-20) TempDir::strip: /var/lib/amavis/tmp/amavis-20230328T011947-03049-mFy8B8Jy
Mar 28 03:30:04 mail amavis[3049]: (03049-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230328T011947-03049-mFy8B8Jy/parts, excl=1
Mar 28 03:30:04 mail postfix/amavis/smtp[10216]: 4PlwDC6tNtz24LN: to=<root@mail.mydomain.com>, orig_to=<root>, relay=127.0.0.1[127.0.0.1]:10026, delay=0.45, delays=0.03/0/0/0.42, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smt
p:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 4PlwDD2VtYz24LM)
Mar 28 03:30:04 mail postfix/qmgr[1813]: 4PlwDC6tNtz24LN: removed
Mar 28 03:30:04 mail amavis[3049]: (03049-20) size: 1347, TIMING [total 427 ms] - SMTP greeting: 1.9 (0%)0, SMTP EHLO: 1.3 (0%)1, SMTP pre-MAIL: 1.2 (0%)1, SMTP MAIL: 1.4 (0%)1, lookup_sql: 3.4 (1%)2, SMTP pre-DATA-flush: 1.3 (0%
)2, SMTP DATA: 35 (8%)11, check_init: 0.9 (0%)11, digest_hdr: 0.9 (0%)11, digest_body_dkim: 0.4 (0%)11, collect_info: 1.3 (0%)12, gen_mail_id: 3.5 (1%)12, mime_decode: 9 (2%)14, get-file-type1: 21 (5%)19, parts_decode: 0.3 (0%)19
, check_header: 0.8 (0%)19, AV-scan-1: 71 (17%)36, lookup_sql: 1.6 (0%)37, spam-wb-list: 2.9 (1%)37, SA msg read: 0.4 (0%)37, SA parse: 2.2 (1%)38, SA check: 136 (32%)70, decide_mail_destiny: 3.0 (1%)71, notif-quar: 1.9 (0%)71, w
rite-header: 3.6 (1%)72, fwd-data-dkim: 23 (5%)77, fwd-connect: 17 (4%)81, fwd-mail-pip: 25 (6%)87, fwd-rcpt-pip: 0.2 (0%)87, fwd-data-chkpnt: 0.0 (0%)87, write-header: 0.3 (0%)87, fwd-data-contents: 0.0 (0%)87, fwd-end-chkpnt: 8
(2%)89, prepare-dsn: 0.8 (0%)89, report: 1.2 (0%)90, main_log_entry: 32 (8%)97, sql-update: 11 ...
Mar 28 03:30:04 mail amavis[3049]: (03049-20) ...(3%)100, SMTP pre-response: 0.3 (0%)100, SMTP response: 0.2 (0%)100, unlink-1-files: 0.2 (0%)100, rundown: 0.7 (0%)100
Mar 28 03:30:04 mail amavis[3049]: (03049-20) idle_proc, 6: was busy, 428.4 ms, total idle 7797.388 s, busy 19.762 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) idle_proc, 5: was idle, 0.1 ms, total idle 7797.388 s, busy 19.762 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) ESMTP< QUIT\r\n
Mar 28 03:30:04 mail amavis[3049]: (03049-20) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Mar 28 03:30:04 mail amavis[3049]: (03049-20) switch_to_client_time 480 s, smtp response sent
Mar 28 03:30:04 mail amavis[3049]: (03049-20) SMTP session over, timer stopped
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Requesting process rundown after 20 tasks (and 20 sessions)
Mar 28 03:30:04 mail amavis[3049]: (03049-20) TempDir::DESTROY called
Mar 28 03:30:04 mail amavis[3049]: (03049-20) TempDir removal: empty tempdir is being removed: /var/lib/amavis/tmp/amavis-20230328T011947-03049-mFy8B8Jy
Mar 28 03:30:04 mail amavis[3049]: (03049-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230328T011947-03049-mFy8B8Jy, excl=
Mar 28 03:30:04 mail amavis[3049]: (03049-20) rmdir_recursively: /var/lib/amavis/tmp/amavis-20230328T011947-03049-mFy8B8Jy/parts, excl=
Mar 28 03:30:04 mail amavis[3049]: (03049-20) exiting process_request
Mar 28 03:30:04 mail amavis[3049]: (03049-20) idle_proc, bye: was busy, 10.4 ms, total idle 7797.388 s, busy 19.773 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) load: 0 %, total idle 7797.388 s, busy 19.773 s
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Net::Server: 2023/03/28-03:30:04 Server closing!
Mar 28 03:30:04 mail amavis[3049]: (03049-20) sd_notify (no socket): STATUS=Child processes have been stopped.
Mar 28 03:30:04 mail postfix/cleanup[10213]: 4PlwDD3B0bz24LN: message-id=<4PlwDC6tNtz24LN@mail.mydomain.com>
Mar 28 03:30:04 mail postfix/local[10524]: 4PlwDD2VtYz24LM: to=<root@mail.mydomain.com>, relay=local, delay=0.11, delays=0.02/0.07/0/0.01, dsn=2.0.0, status=sent (forwarded as 4PlwDD3B0bz24LN)
Mar 28 03:30:04 mail postfix/qmgr[1813]: 4PlwDD3B0bz24LN: from=<root@mail.mydomain.com>, size=2824, nrcpt=1 (queue active)
Mar 28 03:30:04 mail postfix/qmgr[1813]: 4PlwDD2VtYz24LM: removed
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Amavis::Out::SQL::Log DESTROY called
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Amavis::Lookup::SQL DESTROY called
Mar 28 03:30:04 mail amavis[3049]: (03049-20) Amavis::Out::SQL::Connection DESTROY called
Mar 28 03:30:04 mail amavis[3049]: (03049-20) disconnecting from SQL
Mar 28 03:30:04 mail postfix/pipe[10221]: 4PlwDD3B0bz24LN: to=<postmaster@mydomain.com>, orig_to=<root@mail.mydomain.com>, relay=dovecot, delay=0.08, delays=0/0/0/0.08, dsn=2.0.0, status=sent (delivered via dovecot servic
e)
The only change for this machine was that I changed ipv4 IP after iredmail install, could this have affected amavis? What can be the cause?
----
Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.