Bug Report

Context

I have an installation of mailserver on kubernetes with authentication on LDAP. I can login in through webmail setup on my mailserver, write and email. When i write email i got a message of success (message sent) but the receiver never received the mail. I try email in my domain and with other mailserver (Yahoo, etc …) but the mail never arrived. After looking the log i see this error postfix/error[10479]: 85E9F660025: to=<cuser@mydomain>, relay=none, delay=0.53, delays=0.38/0.01/0/0.14, dsn=5.1.1, status=bounced (User unknown in virtual alias table)

I tried to debug it myself bit do not succeed sp after many tries, i need help.

What is affected by this bug?

When does this occur?

When i have to received email from another mailbox

How do we replicate the issue?

1. Log in in a client
2. Send an email to any mailbox

Behavior

Actual Behavior

Mail is never received and this message appear in the log postfix/error[10479]: 85E9F660025: to=<cuser@mydomain>, relay=none, delay=0.53, delays=0.38/0.01/0/0.14, dsn=5.1.1, status=bounced (User unknown in virtual alias table)

Expected Behavior

Mail displayed in the receiver’s mailbox

Your Environment

• version: v10.0
• available RAM: 12GB
• Docker version: 1.18
• Docker version (on node): v19.03.7

Environment Variables

  DOMAINNAME: mail.example.com
  DOVECOT_AUTH_BIND: "yes"
  DOVECOT_PASS_ATTRS: mail=user,userPassword=password
  DOVECOT_PASS_FILTER: (&(objectClass=gosaMailAccount)(mail=%u))
  DOVECOT_USER_ATTRS: =home=/var/mail,=uid=5000,=gid=5000
  DOVECOT_USER_FILTER: (&(objectClass=gosaMailAccount)(mail=%u))
  ENABLE_CLAMAV: "1"
  ENABLE_FAIL2BAN: "1"
  ENABLE_LDAP: "1"
  ENABLE_POSTGREY: "1"
  ENABLE_SASLAUTHD: "0"
  ENABLE_SPAMASSASSIN: "1"
  HOSTNAME: mail.example.com
  LDAP_BIND_DN: cn=admin,dc=mail,dc=example,dc=com
  LDAP_BIND_PW: xxxxxxxxx
  LDAP_QUERY_FILTER_ALIAS: (&(objectClass=gosaMailAccount)(mail=%u))
  LDAP_QUERY_FILTER_DOMAIN: (|(mail=*@%s)(mailalias=*@%s)(mailGroupMember=*@%s))
  LDAP_QUERY_FILTER_GROUP: (&(|(memberof=group1,ou=groups,dc=mail,dc=example,dc=com))
  LDAP_QUERY_FILTER_USER: (&(objectClass=gosaMailAccount)(mail=%u))
  LDAP_SEARCH_BASE: ,dc=example,dc=com
  LDAP_SERVER_HOST: oldap.default
  ONE_DIR: "1"
  OVERRIDE_HOSTNAME: mail.example.com
  PERMIT_DOCKER: connected-networks
  POSTFIX_MESSAGE_SIZE_LIMIT: "100000000"
  POSTMASTER_ADDRESS: user@example.com
  SASLAUTHD_LDAP_BIND_DN: cn=admin,dc=example,dc=com
  SASLAUTHD_LDAP_FILTER: (&(objectClass=gosaMailAccount)(mail=%u))
  SASLAUTHD_LDAP_PASSWORD: xxxxxxxx
  SASLAUTHD_LDAP_SEARCH_BASE: dc=mail,dc=example,dc=com
  SASLAUTHD_LDAP_SERVER: oldap.default
  SASLAUTHD_MECHANISMS: ldap
  SPAMASSASSIN_SPAM_TO_INBOX: "1"

Relevant Stack Traces

IN OPENLDAP IT SEEM TO FIND THE USER

# BEGIN
60c49ef3 conn=15415 op=276 SRCH base="dc=example,dc=com" scope=2 deref=0 filter="(&(objectClass=gosaMailAccount)(mail=user@example.com))" 
60c49ef3 conn=15415 op=276 SRCH attr=mail 
60c49ef3 conn=15415 op=276 SEARCH RESULT tag=101 err=0 nentries=1 text= 
60c49ef3 conn=15415 op=277 BIND anonymous mech=implicit ssf=0 
60c49ef3 conn=15415 op=277 BIND dn="uid=user,ou=people,ou=SSIE,ou=personnels,dc=example,dc=com" method=128 
60c49ef3 conn=15415 op=277 BIND dn="uid=user,ou=people,ou=SSIE,ou=personnels,dc=example,dc=com" mech=SIMPLE ssf=0 
# END

LOG on MAILSERVER

# BEGIN
Jun 11 10:52:14 mailserver-6bb6c9777b-lwqsb amavis[10559]: (05796-04) SA info: util: setuid: ruid=112 euid=112 rgid=114 114 egid=114 114 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) DONE SA check (0) 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline spam_scan_sa - deadline in 478.0 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer spam_scan_sa: timer 287, was 475, deadline in 478.0 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) spam_scan: score=-0.999 autolearn=ham autolearn_force=no tests=[ALL_TRUSTED=-1,URIBL_BLOCKED=0.001] recips=0 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline spam_scan - deadline in 478.0 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer spam_scan: timer 287, was 287, deadline in 478.0 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="2" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_tag_level] => true,  "user@example.com" matches, result="2", matching_key="(constant:2)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="6.31" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_tag2_level] => true,  "user@example.com" matches, result="6.31", matching_key="(constant:6.31)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_tag3_level] => undef, "user@example.com" does not match 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="6.31" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_kill_level] => true,  "user@example.com" matches, result="6.31", matching_key="(constant:6.31)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) final_destiny (ccat=0) is PASS, recip user@example.com 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) final_destiny PASS, recip user@example.com 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) do_notify_and_quar: ccat=Clean (1,0) ("1":Clean, "0":CatchAll) ccat_block=(), qar_mth= 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) do_notify_and_quarantine: not quarantining, q_method off 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) skip admin notification, no administrators 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) do_notify_and_quarantine - done 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (opaque) matches, result="smtp:[127.0.0.1]:10025" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [forward_method] => true,  "user@example.com" matches, result="smtp:[127.0.0.1]:10025", matching_key="(opaque:smtp:[127.0.0.1]:10025)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) delivery method is 1, recips: user@example.com 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="2" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_tag_level] => true,  "user@example.com" matches, result="2", matching_key="(constant:2)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="6.31" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_tag2_level] => true,  "user@example.com" matches, result="6.31", matching_key="(constant:6.31)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) headers CLUSTERING: NEW CLUSTER <user@example.com>: score=-0.999, tag=0, tag2=0, local=1, bl=, s=, mangle= 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) header encoded (all-ASCII): X-Virus-Scanned: Yes 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) header: X-Virus-Scanned: Yes\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) fwd: scanner provided a header field X-Spam-Checker-Version, inhibited by %allowed_added_header_fields 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) fwd: scanner provided a header field X-Spam-Level, but we preferred our own 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) fwd: scanner provided a header field X-Spam-Status, but we preferred our own 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) headers CLUSTERING: done all 1 recips in one go 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) about to connect to smtp:[127.0.0.1]:10025, fsY1RJa-BHkG FWD from <user@example.com> -> <user@example.com> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline fwd_init - deadline in 478.0 s, set to 479.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp session: setting up a new session 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) establish_or_refresh, state: down 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) connected to [127.0.0.1]:10025 successfully 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=1, flush=0, wr=0, timeout=35 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/smtpd[10478]: connect from localhost[127.0.0.1] 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: receiving 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop read 27 chars< 220 mail.example.com ESMTP\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp greeting: 220 mail.example.com ESMTP, dt: 3.3 ms 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp cmd> EHLO localhost 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=0, flush=1, wr=1, timeout=300 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: sending 16 chars 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop sent 16> EHLO localhost\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=1, flush=0, wr=0, timeout=300 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: receiving 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop read 187 chars< 250-mail.example.com\r\n250-PIPELINING\r\n250-SIZE 100000000\r\n250-ETRN\r\n250-STARTTLS\r\n250-AUTH PLAIN LOGIN\r\n250-AUTH=PLAIN LOGIN\r\n250-ENHANCEDSTATUSCODES\r\n250-8BITMIME\r\n250-DSN\r\n250 CHUNKING\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp resp to EHLO: 250 mail.example.com\nPIPELINING\nSIZE 100000000\nETRN\nSTARTTLS\nAUTH PLAIN LOGIN\nAUTH=PLAIN LOGIN\nENHANCEDSTATUSCODES\n8BITMIME\nDSN\nCHUNKING 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) tls active=0, capable=1, sec_level=0 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) Remote host presents itself as: mail.example.com, handles DSN, PIPELINING, 8BITMIME 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) AUTH not needed, user='', MTA offers 'PLAIN LOGIN' 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp cmd> MAIL FROM:<user@example.com> BODY=8BITMIME 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) orcpt_encode rfc822, xxxxx@yahoo.fr, encode_for_smtp 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp cmd> RCPT TO:<user@example.com> ORCPT=rfc822;xxxxx@yahoo.fr 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp cmd> DATA 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=0, flush=1, wr=1, timeout=120 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: sending 123 chars 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop sent 123> MAIL FROM:<user@example.com> BODY=8BITMIME\r\nRCPT TO:<user@example.com> ORCPT=rfc822;xxxxx@yahoo.fr\r\nDATA\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=1, flush=0, wr=0, timeout=300 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/smtpd[10478]: 85E9F660025: client=localhost[127.0.0.1] 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: receiving 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop read 65 chars< 250 2.1.0 Ok\r\n250 2.1.5 Ok\r\n354 End data with <CR><LF>.<CR><LF>\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp resp to MAIL (pip): 250 2.1.0 Ok 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp resp to RCPT (pip) (<user@example.com>): 250 2.1.5 Ok 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp resp to DATA: 354 End data with <CR><LF>.<CR><LF> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) write_header: 1, Amavis::Out::SMTP::Protocol=HASH(0x564d804eafb0) 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=1, flush=0, wr=1, timeout=478.987 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: sending 763 chars 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop sent 763> X-Virus-Scanned: Yes\r\nReceived: from webmail.example.com (10-42-11-33.roundcube.mailserver.svc.cluster.local [10.42.11.33])\r\n\tby mail.example.com (Postfix) with ESMTPA id D8D9B66008A\r\n\tfor <mamiapatrick [...] 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: needline=1, flush=0, wr=0, timeout=478.987 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/cleanup[10465]: 85E9F660025: message-id=<0c575f2a007b9c3361eb6c491381eaa6@example.com> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb dovecot: imap-login: Login: user=<user@example.com>, method=PLAIN, rip=10.42.11.33, lip=10.42.11.40, mpid=10563, session=<XpEFTXvEJuQKKgsh> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/qmgr[1904]: 85E9F660025: from=<user@example.com>, size=970, nrcpt=1 (queue active) 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop: receiving 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rw_loop read 37 chars< 250 2.0.0 Ok: queued as 85E9F660025\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) smtp resp to data-dot (<user@example.com>): 250 2.0.0 Ok: queued as 85E9F660025, dt: 372.6 ms 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) Amavis::Out::SMTP::Session close, keeping connection 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline fwd-end-chkpnt - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer fwd-end-chkpnt: timer 287, was 0, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) fsY1RJa-BHkG FWD from <user@example.com> -> <user@example.com>, BODY=8BITMIME 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 85E9F660025 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline forwarding - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer forwarding: timer 287, was 287, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) DSN: sender NOT credible, SA: -0.999, <user@example.com> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup: (scalar) matches, result="10" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) lookup [spam_dsn_cutoff_level_bysender] => true,  "user@example.com" matches, result="10", matching_key="(constant:10)" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) dsn: from MTA 250 NonBlocking:Clean <user@example.com> -> <user@example.com>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=1, destiny=1, mta_resp: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 85E9F660025" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) DSN: SUCC from MTA 250 NonBlocking:Clean, no DSN requested: <user@example.com> -> <user@example.com> 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) delivery_status_notification: notif 0 bytes, suppressed: no 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) one_response_for_all, per_recip_capable: N, suppressed: N 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) one_response_for_all <user@example.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 85E9F660025' 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) 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 85E9F660025 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline delivery-notification - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer delivery-notification: timer 287, was 287, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) status counters: InMsgsStatus{Relayed,RelayedUntagged,RelayedUntaggedInbound} 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline snmp-counters - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer snmp-counters: timer 287, was 287, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/trivial-rewrite[10464]: warning: do not list domain example.com in BOTH virtual_alias_domains and virtual_mailbox_domains 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) orcpt_encode rfc822, xxxxx@yahoo.fr, smtputf8 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) Passed CLEAN {RelayedInbound}, [10.42.11.33]:58694 <user@example.com> -> <user@example.com>, Queue-ID: D8D9B66008A, Message-ID: <0c575f2a007b9c3361eb6c491381eaa6@example.com>, mail_id: fsY1RJa-BHkG, Hits: -0.999, size: 738, queued_as: 85E9F660025, 2447 ms 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline main_log_entry - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer main_log_entry: timer 287, was 287, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) TIMING-SA total 1885 ms - parse: 2.2 (0.1%), extract_message_metadata: 15 (0.8%), get_uri_detail_list: 2.2 (0.1%), tests_pri_-1000: 29 (1.5%), tests_pri_-950: 2.5 (0.1%), tests_pri_-900: 2.2 (0.1%), tests_pri_-400: 1.77 (0.1%), tests_pri_0: 1543 (81.8%), check_spf: 0.57 (0.0%), check_dkim_signature: 1.15 (0.1%), check_dkim_adsp: 15 (0.8%), poll_dns_idle: 7 (0.4%), check_razor2: 1009 (53.5%), check_pyzor: 432 (22.9%), tests_pri_500: 8 (0.5%), learn: 266 (14.1%), b_learn: 261 (13.8%), b_count_change: 11 (0.6%), get_report: 0.84 (0.0%) 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) updating snmp variables in BDB 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline check done - deadline in 477.6 s, set to 287.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer check done: timer 287, was 287, deadline in 477.6 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) sending SMTP response: "250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 85E9F660025" 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) ESMTP> 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 85E9F660025 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) switch_to_client_time 480 s, smtp response sent 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/smtp[10466]: D8D9B66008A: to=<user@example.com>, orig_to=<xxxxx@yahoo.fr>, relay=127.0.0.1[127.0.0.1]:10024, delay=3.1, delays=0.62/0.01/0.01/2.5, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 85E9F660025) 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) TempDir::strip: /var/lib/amavis/tmp/amavis-20210611T101253-05796-OKneKyvG 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) rmdir_recursively: /var/lib/amavis/tmp/amavis-20210611T101253-05796-OKneKyvG/parts, excl=1 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb postfix/qmgr[1904]: D8D9B66008A: removed 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) size: 738, TIMING [total 2459 ms] - SMTP greeting: 3.6 (0%)0, SMTP EHLO: 2.5 (0%)0, SMTP pre-MAIL: 4.2 (0%)0, SMTP MAIL: 3.0 (0%)1, SMTP pre-DATA-flush: 4.1 (0%)1, SMTP DATA: 31 (1%)2, check_init: 1.3 (0%)2, digest_hdr: 1.1 (0%)2, digest_body: 1.1 (0%)2, collect_info: 3.8 (0%)2, mime_decode: 13 (1%)3, get-file-type1: 41 (2%)5, parts_decode: 0.5 (0%)5, check_header: 1.5 (0%)5, AV-scan-1: 29 (1%)6, spam-wb-list: 3.0 (0%)6, SA msg read: 1.1 (0%)6, SA parse: 3.9 (0%)6, SA check: 1879 (76%)83, decide_mail_destiny: 11 (0%)83, notif-quar: 0.6 (0%)83, fwd-connect: 11 (0%)83, fwd-mail-pip: 3.9 (0%)84, fwd-rcpt-pip: 0.5 (0%)84, fwd-data-chkpnt: 0.1 (0%)84, write-header: 1.4 (0%)84, fwd-data-contents: 0.1 (0%)84, fwd-end-chkpnt: 375 (15%)99, prepare-dsn: 3.6 (0%)99, report: 3.1 (0%)99, main_log_entry: 9 (0%)100, update_snmp: 5 (0%)100, SMTP pre-response: 1.1 (0%)100, SMTP response: 0.9 (0%)100, unlink-1-files: 0.8 (0%)100, rundown: 1.5 (0%)100 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) idle_proc, 6: was busy, 2444.3 ms, total idle 2333.224 s, busy 29.543 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) idle_proc, 5: was idle, 0.3 ms, total idle 2333.225 s, busy 29.543 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) ESMTP< QUIT\r\n 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) switch_to_client_time 480 s, smtp response sent 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) SMTP session over, timer stopped 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) exiting process_request 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) idle_proc, bye: was busy, 4.5 ms, total idle 2333.225 s, busy 29.547 s 
Jun 11 10:52:15 mailserver-6bb6c9777b-lwqsb amavis[5796]: (05796-04) load: 1 %, total idle 2333.225 s, busy 29.547 s 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb dovecot: imap(user@example.com)<10563><XpEFTXvEJuQKKgsh>: Logged out in=44 out=619 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/error[10479]: 85E9F660025: to=<user@example.com>, relay=none, delay=0.53, delays=0.38/0.01/0/0.14, dsn=5.1.1, status=bounced (User unknown in virtual alias table) 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/cleanup[10554]: 126DE66008A: message-id=<20210611105216.126DE66008A@mail.example.com> 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/bounce[10480]: 85E9F660025: sender non-delivery notification: 126DE66008A 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/qmgr[1904]: 126DE66008A: from=<>, size=2874, nrcpt=1 (queue active) 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/trivial-rewrite[10464]: warning: do not list domain example.com in BOTH virtual_alias_domains and virtual_mailbox_domains 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/qmgr[1904]: 85E9F660025: removed 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/error[10479]: 126DE66008A: to=<user@example.com>, relay=none, delay=0.3, delays=0.13/0.01/0/0.16, dsn=5.1.1, status=bounced (User unknown in virtual alias table) 
Jun 11 10:52:16 mailserver-6bb6c9777b-lwqsb postfix/qmgr[1904]: 126DE66008A: removed 
# END