1 Topic by t.klawa

  • t.klawa
  • Member
  • Offline
  • Registered: 2020-06-05
  • Posts: 3

Topic: Terribly slow SMTP submission

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

Hi,

I'm struggling with the issue for over a week now and have run out of ideas and things to read in google...

I've got huge delays on first phase - SMTP submission. Example e-mail (very small message):

Jun  5 17:09:34 mail postfix/amavis/smtp[129249]: ECB4418058913: to=<t.klawa@mydomain.pl>, relay=127.0.0.1[127.0.0.1]:10026, delay=62, delays=62/0/0/0.11, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:

postfix-logwatch delivery delays confirms that everything is happening before queue:


=== Delivery Delays Percentiles ============================================================
                    0%       25%       50%       75%       90%       95%       98%      100%
--------------------------------------------------------------------------------------------
Before qmgr       0.00      4.60     12.00    375.00   1959.00   4860.00  51046.42  65753.00
In qmgr           0.00      0.37      1.10      9.00    123.00    365.00   1512.00   2481.00
Conn setup        0.00      0.00      0.00      0.00      0.01      0.02      0.03     11.00
Transmission      0.00      0.32      0.37      5.30      8.00     12.00     22.00    190.00
Total             0.05      6.80     16.00    605.75   2352.00   5017.55  51048.42  65755.00
============================================================================================


I've tried everything i could... for ex. :
- disabling amavis
- disabling iredAPD
- checking DNS answer time (using local DNS)
- disabling postscreen
- increasing every connection/process limit i thought was relevant
- many, many different things

The slowest moment of SMTP submission is right after "RCPT TO:"
I often receive connection timeouts at this point if i try to send for example 20-30 emails at once. Up to lets say 10 messages everything works fine. Slow but no timeouts...

Finaly i've turned on debugging and found what are the slowest moments of SMTP transaction (observe the time):
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: < unknown[172.18.10.161]: STARTTLS
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: > unknown[172.18.10.161]: 220 2.0.0 Ready to start TLS
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: send attr request = seed
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: send attr size = 32
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: private/tlsmgr: wanted attribute: status
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: input attribute value: 0
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: private/tlsmgr: wanted attribute: seed
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: input attribute name: seed
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: input attribute value: b04kuutwHGFKsr36pem8EQZd/X4hZXhBr+pb87UFGXg=
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: private/tlsmgr: wanted attribute: (list terminator)
Jun  5 17:08:24 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: status
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: input attribute value: 1
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: value
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: input attribute name: value
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: input attribute value: (end)
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: (list terminator)
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap/virtual_alias_maps.cf flags=lock|fold_fix key=t.klawa@mydomain.pl -> status=1 result=
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: send attr request = lookup
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: send attr table = ldap:/etc/postfix/ldap/virtual_group_maps.cf
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: send attr flags = 16448
Jun  5 17:08:46 mail postfix/submission/smtpd[131121]: send attr key = t.klawa@mydomain.pl
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: status
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: input attribute value: 1
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: value
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: input attribute name: value
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: input attribute value: (end)
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: (list terminator)
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap/virtual_group_maps.cf flags=lock|fold_fix key=t.klawa@mydomain.pl -> status=1 result=
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: send attr request = lookup
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: send attr table = ldap:/etc/postfix/ldap/virtual_group_members_maps.cf
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: send attr flags = 16448
Jun  5 17:08:50 mail postfix/submission/smtpd[131121]: send attr key = t.klawa@mydomain.pl
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: status
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: input attribute value: 1
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: value
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: input attribute name: value
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: input attribute value: (end)
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: (list terminator)
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap/virtual_group_members_maps.cf flags=lock|fold_fix key=t.klawa@mydomain.pl -> status=1 result=
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: send attr request = lookup
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: send attr table = ldap:/etc/postfix/ldap/catchall_maps.cf
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: send attr flags = 16448
Jun  5 17:08:53 mail postfix/submission/smtpd[131121]: send attr key = t.klawa@mydomain.pl
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: status
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: input attribute value: 1
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: value
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: input attribute name: value
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: input attribute value: (end)
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: (list terminator)
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap/virtual_group_members_maps.cf flags=lock|fold_fix key=@mydomain.pl -> status=1 result=
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: send attr request = lookup
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: send attr table = ldap:/etc/postfix/ldap/catchall_maps.cf
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: send attr flags = 16448
Jun  5 17:09:16 mail postfix/submission/smtpd[131121]: send attr key = @mydomain.pl
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: status
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute name: status
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute value: 1
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: value
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute name: value
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute value: (end)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: private/proxymap socket: wanted attribute: (list terminator)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: dict_proxy_lookup: table=ldap:/etc/postfix/ldap/catchall_maps.cf flags=lock|fold_fix key=@mydomain.pl -> status=1 result=
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: maps_find: virtual_alias_maps: @mydomain.pl: not found
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: mail_addr_find: t.klawa@mydomain.pl -> (not found)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: connect to subsystem public/cleanup
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: public/cleanup socket: wanted attribute: queue_id
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute name: queue_id
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute value: ECB4418058913
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: public/cleanup socket: wanted attribute: (list terminator)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: input attribute name: (end)
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: send attr flags = 178
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: ECB4418058913: client=unknown[172.18.10.161], sasl_method=login, sasl_username=t.klawa.test@sklep.mydomain.pl
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: > unknown[172.18.10.161]: 250 2.1.5 Ok
Jun  5 17:09:21 mail postfix/submission/smtpd[131121]: watchdog_pat: 0x564c20a93140



There are like 20 sec gaps in the transaction! Server is a very fast Hyper-V VM with 12 cores, 24 gb RAM and SSD Drives. Lot's of free rescources. CPU is doing nothing...


What should I look at? What might be the problem? It's killing me...

----

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,088

Re: Terribly slow SMTP submission

Do you use a fast DNS server in /etc/resolv.conf (and /var/spool/postfix/etc/resolv.conf)?

3 Reply by t.klawa

  • t.klawa
  • Member
  • Offline
  • Registered: 2020-06-05
  • Posts: 3

Re: Terribly slow SMTP submission

I'm was using my network DNS servers, which are connected over 10gbit vm-network and response times are fast.

To get that out of the way i just installed bind, and pointed both resolve.conf's to local host.

Used DIG to test this:
First lookup for random domain (iredmail.org): 263 msec
Second lookup for the same iredmail.org: 0 msec

DNS cache is working as it supposed to and it's fast. Delays must be caused by something else...recipient verification maybe? Something with Dovecot / ldap? Not sure...no idea really sad

4 Reply by ZhangHuangbin

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

Re: Terribly slow SMTP submission

please disable the debug mode in Postfix first, then reproduce the issue.
Show us full original log lines of this smtp session in Postfix log file.

WARNING: do not use 'grep' to filter the log lines. We need log lines of full smtp session, from smtp connection starts, until mail delivered to mailbox (or remote mail server).

5 Reply by t.klawa

  • t.klawa
  • Member
  • Offline
  • Registered: 2020-06-05
  • Posts: 3

Re: Terribly slow SMTP submission

Finaly i figured out from the logs above, that Postfix is experiencing massive delays making queries to LDAP server. We are using freeIPA, we have three servers on local network.

While sending single email postfix is making multiple queries, which are very slow. At the moment I turned off those i think we don't need: sender_bcc_maps, recipient_bcc_maps, virtual_alias_maps, sender_dependent_relayhost_maps

We lose some of the funcionality, but there is a huge gain in speed - sending 50 test emails went down from 3 minutes to 10 seconds.

If anybody can give some advice how to further diagnose and speedup the queries to freeIPA i would appreciate it very much. We've got only about 300 users, and freeIPA servers are quite fast (16 Gb Ram, 16 Cores). Is it possible that something is missconfigured in my iRedMail or should I foucus on LDAP servers?

6 Reply by ZhangHuangbin

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

Re: Terribly slow SMTP submission

is it possible an issue of networking?