Greetings all. I’ve been running qmail on my servers and vms for about 20 years
and it’s mostly worked great, but I’m having a thumper of a slowdown problem on
my current setup and I can’t get to the bottom of it… any help appreciated.
The environment is a very lightly-used private VM running centos7 and the
following packages:
[root@radbug ~]# yum list installed | grep qmail
qmail.x86_64 1.03-2.2.1.qt.el7 @qmt-current
qmailadmin.x86_64 1.2.16-3.2.qt.el7 @qmt-current
qmailmrtg.x86_64 4.2-3.qt.el7 @qmt-current
I’ve narrowed it down to a delay shown in /var/log/qmail/submission/current,
when I send a test message to myself at another address, using my vm as my mail
server. The first lines hit immediately when I click “send” in the mail client,
but then it takes a full minute between the tcpserver “end” message and
whatever preceded it, during which time my mail client hangs at “sending…”:
(annotations [*** like this ***] inline are mine, obviously, and
addresses/servers replaced with caps but the IPs are unchanged):
2021-01-30 13:42:52.255716500 tcpserver: status: 0/100
[*** message sent......... ***]
2021-01-30 13:47:33.912724500 tcpserver: status: 1/100
2021-01-30 13:47:33.912947500 tcpserver: pid 6009 from 24.62.203.29
2021-01-30 13:47:33.912948500 tcpserver: ok 6009 MYHOST:104.236.46.99:587
:24.62.203.29::55124
[*** waiting... one minute 4 seconds pass ***]
2021-01-30 13:48:37.899374500 tcpserver: end 6009 status 256
2021-01-30 13:48:37.899376500 tcpserver: status: 0/100
2021-01-30 13:48:37.930988500 tcpserver: status: 1/100
2021-01-30 13:48:37.931122500 tcpserver: pid 6021 from 24.62.203.29
2021-01-30 13:48:37.931198500 tcpserver: ok 6021 MYHOST:104.236.46.99:587
:24.62.203.29::55129
2021-01-30 13:48:38.263537500 CHKUSER accepted sender: from
<m...@myserver.com:m...@myserver.com:> remote
<[10.0.98.178]:unknown:24.62.203.29> rcpt <> : sender accepted
2021-01-30 13:48:38.327973500 CHKUSER relaying rcpt: from
<m...@myserver.com:m...@myserver.com:> remote
<[10.0.98.178]:unknown:24.62.203.29> rcpt <m...@otherserver.com> : client
allowed to relay
2021-01-30 13:48:38.327975500 policy_check: local m...@myserver.com -> remote
m...@otherserver.com (AUTHENTICATED SENDER)
2021-01-30 13:48:38.327976500 policy_check: policy allows transmission
[*** waiting... (message received) then one more minute passes ***]
2021-01-30 13:49:38.403478500 tcpserver: end 6021 status 0
2021-01-30 13:49:38.403479500 tcpserver: status: 0/100
It’s very consistent in this timing, and loads on the server are basically 0,
nothing in /var/log/messages or anywhere else that I can see. Vpopmail is using
mysql, but it isn’t logging any slow queries, and this is more or less the only
thing happening on the box. It’s been doing it for a while now, maybe a month
or two? I don’t send much mail so I didn’t lean into it too hard when it
started happening, but now it’s really annoying me and I want to get to the
bottom of it. (Inbound mail TO the server from other locations (like the auto
response to the “subscribe” message I sent to the list just now) lands
instantly.)
My /etc/tcprules.d/tcp.smtp: (I thought it might have been something about
domain keys, so I removed that but it hasn’t made any difference)
127.:allow,BADMIMETYPE="",BADLOADERTYPE="M",CHKUSER_RCPTLIMIT="50",CHKUSER_WRONGRCPTLIMIT="10",NOP0FCHECK="1",QMAILQUEUE="/var/qmail/bin/simscan"
My /var/qmail/supervise/submission/run:
#!/bin/sh
QMAILDUID=`id -u vpopmail`
NOFILESGID=`id -g vpopmail`
MAXSMTPD=`cat /var/qmail/control/concurrencyincoming`
SMTPD="/var/qmail/bin/qmail-smtpd"
TCP_CDB="/etc/tcprules.d/tcp.smtp.cdb"
HOSTNAME=`hostname`
VCHKPW="/home/vpopmail/bin/vchkpw"
export REQUIRE_AUTH=1
exec /usr/bin/softlimit -m 128000000 \
/usr/bin/tcpserver -v -R -H -l $HOSTNAME -x $TCP_CDB -c "$MAXSMTPD" \
-u "$QMAILDUID" -g "$NOFILESGID" 0 587 \
$SMTPD $VCHKPW /bin/true 2>&1
In case it’s relevant, my /var/qmail/supervise/smtp/run:
#!/bin/sh
QMAILDUID=`id -u vpopmail`
NOFILESGID=`id -g vpopmail`
MAXSMTPD=`cat /var/qmail/control/concurrencyincoming`
SPAMDYKE="/usr/bin/spamdyke"
SPAMDYKE_CONF="/etc/spamdyke/spamdyke.conf"
SMTPD="/var/qmail/bin/qmail-smtpd"
TCP_CDB="/etc/tcprules.d/tcp.smtp.cdb"
HOSTNAME=`hostname`
VCHKPW="/home/vpopmail/bin/vchkpw"
REQUIRE_AUTH=0
exec /usr/bin/softlimit -m 64000000 \
/usr/bin/tcpserver -v -R -H -l $HOSTNAME -x $TCP_CDB -c "$MAXSMTPD" \
-u "$QMAILDUID" -g "$NOFILESGID" 0 smtp \
$SPAMDYKE --config-file $SPAMDYKE_CONF \
$SMTPD $VCHKPW /bin/true 2>&1
I tried removing spamdyke from this just to see if it made a difference after
“qmailctl restart”; it didn’t make a difference.
It’s very consistent in this timing, and loads on the server are basically 0,
nothing in /var/log/messages or anywhere else that I can see. Vpopmail is using
mysql, but it isn’t logging any slow queries, and this is more or less the only
thing happening on the box. The mail does go out, but it always takes a minute
to clear the outbox from my mail client, and I can’t figure out why it’s
happening.
Any advice or dope-slaps much appreciated. Going to click “send” on this now
and wait one minute for it to get sent… >:-(
