Topic: qpsmtpd enquerying very slow (1.5 to 3 minutes per message)

[TAD2020]

Since installing updates 3 weeks ago, incoming mail it taking a very long time to be queued to our 9.2 server.

The update was done quickly early AM Jan 26th when all users were unable to send email suddenly ("452 Message denied temporarily"). Since it was one of those 5AM still sleeping emergencies, I don't fully remember what was happening, but I recall some errors relating to the antivirus. Doing the software update via server-manager resolved the problem and I figured it must have been caused by a failure to pull def updates.

Since then, all mail received through port 25 is very slow. Our external mail comes though a Baracuda box first then passed to SME via 25. Our copiers also use 25 for sending scans via email to ourselves (the machines have no options to use anything other than 25), I wouldn't have noticed the issue as quickly if scans weren't taking several minutes to be received.

Only mail received via 25 is affected. Port 465 SSL/TLS is pretty much fine, it might be slightly slower than before, but its to the point any of my users are complaining about that.

For testing, I disabled virus and spam filtering (Baracuda , so not concerned leaving those disable). This has no effect.

I setup wireshark to debug the mail exchange and found that after the full email body has been transmitted, the server was takes 1.5 to 3 minutes to respond with queued. Going from there, I watched 'tail -f /var/log/qpsmtpd/current' and found it would sit after "spooling message to disk" for that entire delay period.

Code: [Select]

@400000005a8629ae388d93c4 18678 Accepted connection 0/60 from 192.168.1.25 / Unknown
@400000005a8629ae388d97ac 18678 Connection from Unknown [192.168.1.25]
@400000005a8629ae3b418c4c 18678 (connect) relay: skip, no match
@400000005a8629ae3b4600ec 18678 220 mail.DOMAIN.com ESMTP
@400000005a8629ae3b4e6174 18678 dispatching EHLO mail2.DOMAIN.com
@400000005a8629ae3b5f4994 18678 250-DOMAIN.com Hi Unknown [192.168.1.25]
@400000005a8629ae3b601c84 18678 250-PIPELINING
@400000005a8629ae3b60cc4c 18678 250-8BITMIME
@400000005a8629ae3b6183e4 18678 250-SIZE 35000000
@400000005a8629ae3b6233ac 18678 250 STARTTLS
@400000005a8629ae3b6a49fc 18678 dispatching STARTTLS
@400000005a8629ae3b6c3244 18678 220 Go ahead with TLS
@400000005a8629af0151556c 18678 (unrecognized_command) tls: TLS setup returning
@400000005a8629af14674634 18678 dispatching EHLO mail2.DOMAIN.com
@400000005a8629af1470a88c 18678 250-DOMAIN.com Hi Unknown [192.168.1.25]
@400000005a8629af14717794 18678 250-PIPELINING
@400000005a8629af14722b44 18678 250-8BITMIME
@400000005a8629af1472e2dc 18678 250-SIZE 35000000
@400000005a8629af1473f44c 18678 250 AUTH PLAIN LOGIN
@400000005a8629af148fb5c4 18678 dispatching MAIL FROM:<SOMEONE@gmail.com> SIZE=3840
@400000005a8629af149b891c 18678 (mail) naughty: pass
@400000005a8629af14a299b4 18678 250 <SOMEONE@gmail.com>, sender OK - how exciting to get mail from you!
@400000005a8629af14a7d58c 18678 dispatching RCPT TO:<USER@DOMAIN.com>
@400000005a8629af14b25124 18678 (rcpt) badrcptto: pass
@400000005a8629af14b450dc 18678 (rcpt) check_goodrcptto: stripping '-' extensions
@400000005a8629af15eaadfc 18678 (rcpt) rcpt_ok: pass: DOMAIN.com in rcpthosts
@400000005a8629af15ecf404 18678 250 <USER@DOMAIN.com>, recipient ok
@400000005a8629af15f1a724 18678 dispatching DATA
@400000005a8629af15f56bfc 18678 354 go ahead
@400000005a8629af1703692c 18678 spooling message to disk

[Pauses here for a couple minutes]

@400000005a862a0917cbed34 18678 (data_post_headers) dkim: DNS query timeout for gmail.com
@400000005a862a0917cbf504
@400000005a862a0917ce6dd4 18678 (data_post_headers) dkim: karma -1 (-1)
@400000005a862a0917d013b4 18678 (data_post_headers) dkim: domain: gmail.com, selector: 20161025, result: invalid (public key: DNS query timeout for 20161025._domainkey.gmail.com)
@400000005a862a0917d0e2bc 18678 (data_post_headers) dkim: error, invalid signature, unhandled
@400000005a862a0917e368ec 18678 (data_post) bogus_bounce: pass, not a null sender
@400000005a862a0917f13814 18678 (data_post) headers: pass
@400000005a862a0917f30cd4 18678 (data_post) naughty: pass
@400000005a862a09187aa3c4 18678 (queue) logging::logterse: ` 192.168.1.25       Unknown mail2.DOMAIN.com   <SOMEONE@gmail.com>     <USER@DOMAIN.com>  queued          <f3d726b7-d52e-7714-1254-41d325d977b7@gmail.com>
@400000005a862a0918935414 18718 (queue) queue::qmail_2dqueue: (for 18678) Queuing to /var/qmail/bin/qmail-queue
@400000005a862a091930343c 18678 250 Queued! 1518742015 qp 18718 <f3d726b7-d52e-7714-1254-41d325d977b7@gmail.com>
@400000005a862a09194016a4 18678 dispatching QUIT
@400000005a862a0919445494 18678 221 DOMAIN.com closing connection. Have a wonderful day.
@400000005a862a091946e0ec 18678 click, disconnecting
@400000005a862a0a026c0884 1802 cleaning up after 18678
The mail queue isn't clogging either (had this issue a couple times many years ago when flooded with spam), just slow per message:

Code: [Select]

Mail Log File Analysis
Report generated: Thu 15 Feb 2018 05:52:11 PM PST

messages in queue: 0
messages in queue but not yet preprocessed: 0

I saw in top that it was using some swap, so I doubled is ram allocation from 6GB to 12GB and assigned it another 3 CPU cores while I had it off. This had no effect on the delay.

Code: [Select]

top - 17:51:13 up 34 min,  1 user,  load average: 0.00, 0.01, 0.00
Tasks: 315 total,   1 running, 314 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.1%us,  0.1%sy,  0.0%ni, 99.9%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:  12329780k total,  1854600k used, 10475180k free,    77896k buffers
Swap:  6127612k total,        0k used,  6127612k free,   698596k cached

Disk space is fine as well:

Code: [Select]

Filesystem            Size  Used Avail Use% Mounted on
/dev/mapper/main-root
                      782G  248G  495G  34% /
tmpfs                 5.9G     0  5.9G   0% /dev/shm
/dev/md0              239M   77M  150M  34% /boot
The server is virtualized on vsphere, its host's load is under 15% and uses a local storage array. No other guests on the host are showing any problems, so I'm certain the issue isn't hardware and has to be related to one of the recent updated packages.

At kind of a lost as to where to go troubleshooting from here and would appreciate input.

[Jean-Philippe Pialasse]

You couldhave found the delay easily by piping the output of the log to tai64nlocal

Your issue is a dns issue

Code: [Select]

@400000005a862a0917cbed34 18678 (data_post_headers) dkim: DNS query timeout for gmail.com



What type of filtering does your baracuda box?
Dkim is not checked on local emails, this explain you do not have issue with those connections

How is configured your server for dns ?

[TAD2020]

You couldhave found the delay easily by piping the output of the log to tai64nlocal

Your issue is a dns issue

Code: [Select]

@400000005a862a0917cbed34 18678 (data_post_headers) dkim: DNS query timeout for gmail.com



What type of filtering does your baracuda box?

Its a Barracuda Spam & Virus Firewall 200, purely doing email filtering and it hosted locally.

Dkim is not checked on local emails, this explain you do not have issue with those connections

This is happening with local connections delivering local mail. Here's a log from one of those exchanges:

Code: [Select]

2018-02-15 08:56:52.383038500 20870 Accepted connection 0/60 from 192.168.1.236 / Unknown
2018-02-15 08:56:52.383141500 20870 Connection from Unknown [192.168.1.236]
2018-02-15 08:56:52.427025500 20870 (connect) relay: skip, no match
2018-02-15 08:56:52.427301500 20870 220 mail.DOMAIN.com ESMTP
2018-02-15 08:56:52.453230500 20870 dispatching EHLO [192.168.1.236]
2018-02-15 08:56:52.454368500 20870 250-DOMAIN.com Hi Unknown [192.168.1.236]
2018-02-15 08:56:52.454412500 20870 250-PIPELINING
2018-02-15 08:56:52.454448500 20870 250-8BITMIME
2018-02-15 08:56:52.454485500 20870 250-SIZE 35000000
2018-02-15 08:56:52.454521500 20870 250 STARTTLS
2018-02-15 08:56:52.455704500 20870 dispatching MAIL FROM:<scanner6@DOMAIN.com>
2018-02-15 08:56:52.456503500 20870 (mail) naughty: pass
2018-02-15 08:56:52.456925500 20870 250 <scanner6@DOMAIN.com>, sender OK - how exciting to get mail from you!
2018-02-15 08:56:52.457765500 20870 dispatching RCPT TO:<USER@DOMAIN.com>
2018-02-15 08:56:52.458444500 20870 (rcpt) badrcptto: pass
2018-02-15 08:56:52.458558500 20870 (rcpt) check_goodrcptto: stripping '-' extensions
2018-02-15 08:56:52.477146500 20870 (rcpt) rcpt_ok: pass: DOMAIN.com in rcpthosts
2018-02-15 08:56:52.477305500 20870 250 <USER@DOMAIN.com>, recipient ok
2018-02-15 08:56:52.478185500 20870 dispatching DATA
2018-02-15 08:56:52.478393500 20870 354 go ahead
2018-02-15 08:56:53.296138500 20870 spooling message to disk

2018-02-15 08:58:13.318796500 20870 (data_post_headers) dkim: DNS query timeout for DOMAIN.com
2018-02-15 08:58:13.318798500
2018-02-15 08:58:13.318798500 20870 (data_post_headers) dkim: error, no signature, no policy
2018-02-15 08:58:13.318799500 20870 (data_post_headers) dkim: result: none
2018-02-15 08:58:13.318799500 20870 (data_post) bogus_bounce: pass, not a null sender
2018-02-15 08:58:13.318909500 20870 (data_post) headers: pass
2018-02-15 08:58:13.319147500 20870 (data_post) naughty: pass
2018-02-15 08:58:13.328366500 20870 (queue) logging::logterse: ` 192.168.1.236 Unknown [192.168.1.236] <scanner6@DOMAIN.com> <USER@DOMAIN.com> queued <20180215085626.0001.CanonTxNo.1873@[192.168.1.236]>
2018-02-15 08:58:13.329827500 20938 (queue) queue::qmail_2dqueue: (for 20870) Queuing to /var/qmail/bin/qmail-queue
2018-02-15 08:58:13.341389500 20870 250 Queued! 1518713893 qp 20938 <20180215085626.0001.CanonTxNo.1873@[192.168.1.236]>
2018-02-15 08:58:13.344269500 20870 dispatching QUIT
2018-02-15 08:58:13.344270500 20870 221 DOMAIN.com closing connection. Have a wonderful day.
2018-02-15 08:58:13.344270500 20870 click, disconnecting
2018-02-15 08:58:14.104749500 1802 cleaning up after 20870

How is configured your server for dns ?

I don't remember exactly, but I think it was setup with the default options for standalone install, which if I remember right, is leave blank to use the installer default global DNS servers. The SME is only used for email as of last year and the only additional role it severed before was web server.

But looking resolve.conf, it has my Windows domain controller then itself set as nameservers.

If it is a DNS problem, why would it have suddenly become an issue after the jan26 updates? No other changes anywhere in the network were done around that time. I be the first to agree it could be a DNS issue, just seems very odd it that it never presented before.

nslookup and dig of my domain return with correct info on the SME server within a sec. Don't know if that means anything, I do know there is much knowledge I lack about DNS, I greatly appreciate any help here.


Dug in to the clamd logs from the 26th (since that was the original issue for this new problem started), its completely filled with this one error:

Code: [Select]

2018-01-26 10:19:16.300697500 ERROR: accept() failed: Partial log dropboxed from that day here since its several MB too large for even pastebin. Every earlier logs rotation is from the 26th and all appear to be just filled with error as above.
https://www.dropbox.com/s/95yr4os62ao08br/clamd_current.txt?dl=0
Server was rebooted at 10:19:34 for the updates and clamd leaves whatever errored state it was in.

[Jean-Philippe Pialasse]

with the new qpsmtpd there are more test depending on the DNS. DKIM is one of them. My bad indeed DKIm is checked also on local.

If you already use a front filter, depending ont he test done there, you do not need to reproduce them again.

What is your SME configuration ? server only or server and gateway ?

If this is the second , what you might call local, could be considered as not local but remote for the SME.

But form the log it really point to the DKIM plugin having issue to contact the DNS. DKIM filter was not enforced by default before.


what gives from the SME Server:

Code: [Select]

dig default_.pialasse.com TXT
 dig _domainkey.pialasse.com TXT
 dig _dmarc.pialasse.com TXTreplacing by a domain you saw in the log

as this is DNS stuff, if you obfuscate the domain it will be harder to help and compere results.

Is there any chance your baracuda is also doing global firewall and filtering dns request that the SME is doing ?


also what returns:

Code: [Select]

config show dnscache
config show dnscache.forwarder
config show tinydns


[TAD2020]

What is your SME configuration ? server only or server and gateway ?

Server only.

what gives from the SME Server:

Code: [Select]

dig default_.pialasse.com TXT
 dig _domainkey.pialasse.com TXT
 dig _dmarc.pialasse.com TXTreplacing by a domain you saw in the log

Code: [Select]

[root@mail ~]# dig default_.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 931
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.wheatleylaw.com.      IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:34:55 2018
;; MSG SIZE  rcvd: 42

[root@mail ~]# dig _domainkey.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 47013
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.wheatleylaw.com.    IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:34:56 2018
;; MSG SIZE  rcvd: 44

[root@mail ~]# dig _dmarc.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 57406
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.wheatleylaw.com.                IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:34:59 2018
;; MSG SIZE  rcvd: 40


[root@mail ~]# dig default_.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 11778
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.gmail.com.            IN      TXT

;; Query time: 31 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:35:43 2018
;; MSG SIZE  rcvd: 36

[root@mail ~]# dig _domainkey.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 28501
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.gmail.com.          IN      TXT

;; Query time: 31 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:35:44 2018
;; MSG SIZE  rcvd: 38

[root@mail ~]# dig _dmarc.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 19210
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.gmail.com.              IN      TXT

;; ANSWER SECTION:
_dmarc.gmail.com.       599     IN      TXT     "v=DMARC1\; p=none\; sp=quarantine\; rua=mailto:mailauth-reports@google.com"

;; Query time: 31 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:35:47 2018
;; MSG SIZE  rcvd: 118

as this is DNS stuff, if you obfuscate the domain it will be harder to help and compere results.
True, I only really need to obfuscate the full email addresses. Already filtering an average of between 3k and 15k spam per day, this is why the Baracuda was absolutely necessary.

Is there any chance your baracuda is also doing global firewall and filtering dns request that the SME is doing ?
Its not setup to be able to do that nor capable. They sell such things as separate products, I have a retaliative base model.

also what returns:

Code: [Select]

config show dnscache
config show dnscache.forwarder
config show tinydns


Code: [Select]

[root@mail ~]# config show dnscache
dnscache=service
    Forwarder=192.168.1.1
    TCPPort=53
    UDPPort=53
    access=private
    status=enabled
[root@mail ~]# config show dnscache.forwarder
dnscache.forwarder=service
    status=enabled
[root@mail ~]# config show tinydns
tinydns=service
    UDPPorts=53
    access=localhost
    status=enabled
192.168.1.1 is the router (pfsense). It uses Google's DNS servers. The only name overrides its forwarder has are for forms.wheatleylaw.com (basic single page intranet site), mail.wheatleylaw.com (current mail FQDN), and wheat-mail.wheatleylaw.com (old mail server FQDN from 11-6 years ago) which all resolve to SME server's local IP.


I should add, while the worst delays I saw in any of my testing was up around 3 minute, I have had a number of users experience longer than 10 minute delays.

EDIT: by JP Pialasse to tidy the quote tags to fix formatting.

[TAD2020]

Forgot to mention that the Baracuda's IP is set as "Address of Internet provider's mail server"

[Jean-Philippe Pialasse]

your issue is that dns are not getting answered correctly. Your SME ask for DNS to  192.168.1.1 which reply
and get that:

Code: [Select]

# dig default_.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 931
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.wheatleylaw.com.      IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 12:34:55 2018
;; MSG SIZE  rcvd: 42
instead of

Code: [Select]

$ dig default_.wheatleylaw.com TXT

; <<>> DiG 9.11.1-P3-RedHat-9.11.1-5.P3.fc26 <<>> default_.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 51798
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 4096
;; QUESTION SECTION:
;default_.wheatleylaw.com. IN TXT

;; AUTHORITY SECTION:
wheatleylaw.com. 300 IN SOA NS69.WORLDNIC.com. namehost.WORLDNIC.com. 117102716 10800 3600 604800 3600

;; Query time: 57 msec
;; SERVER: 127.0.0.1#53(127.0.0.1)
;; WHEN: ven fév 16 16:39:37 EST 2018
;; MSG SIZE  rcvd: 112


Why have you configured  192.168.1.1 as DNS server for the SME ? Further more then to use Google's DNS which are suppose to answer this :

Code: [Select]

$ dig @8.8.8.8 default_.wheatleylaw.com TXT

; <<>> DiG 9.11.1-P3-RedHat-9.11.1-5.P3.fc26 <<>> @8.8.8.8 default_.wheatleylaw.com TXT
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 27474
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 1, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 512
;; QUESTION SECTION:
;default_.wheatleylaw.com. IN TXT

;; AUTHORITY SECTION:
wheatleylaw.com. 1799 IN SOA NS69.WORLDNIC.com. namehost.WORLDNIC.com. 117102716 10800 3600 604800 3600

;; Query time: 108 msec
;; SERVER: 8.8.8.8#53(8.8.8.8)
;; WHEN: ven fév 16 16:48:53 EST 2018
;; MSG SIZE  rcvd: 112

As you see, even google would answer correctly, while we would still not recommend to use Google as resolver So the issue is between your SME and the pfSense.

I would start to let SME to use itself as DNS resolver. Check if your PfSense let the SME connect to remote root DNS to make it work.
If you have some local name to resolve using entries configured in the pfsense, this could be limit to do this.

[TAD2020]

Why have you configured  192.168.1.1 as DNS server for the SME ?

Good question, I don't know. It has never needed to resolve any internal names. I haven't a clue what past incident lead to this configuration.

As you see, even google would answer correctly, while we would still not recommend to use Google as resolver So the issue is between your SME and the pfSense.

I would start to let SME to use itself as DNS resolver. Check if your PfSense let the SME connect to remote root DNS to make it work.
If you have some local name to resolve using entries configured in the pfsense, this could be limit to do this.

Fully agree SME should be using itself for DNS resolve. I had thought it was since that was the way I had always set it when I either have to refresh this one (original migration to SME was 11+ years ago) or setup another one in the past.

What's the proper way to change the DNS config to self?

[Jean-Philippe Pialasse]

go to server manager, domain, configure DNS remove the entry in the field and save. this should be it.

you can retry the dig resolution after that.
I do not know if the pfsense allows the SME to do DNS request or if you should also configure it to allow at least this particular ip to be bale to.

[TAD2020]

go to server manager, domain, configure DNS remove the entry in the field and save. this should be it.

Blanking the input field and saving is having no effect. When I check "Primary corporate DNS server" again, its unchanged.

[TAD2020]

While it clears the table under Manage Domains, its still populated in the settings page, and there is no effect on resolving
https://i.imgur.com/effo8QG.png

DB shows the change though

Code: [Select]

[root@mail ~]# config show dnscache
dnscache=service
    TCPPort=53
    UDPPort=53
    access=private
    status=enabled
[root@mail ~]# config show dnscache.forwarder
dnscache.forwarder=service
    status=enabled
[root@mail ~]# config show tinydns
tinydns=service
    UDPPorts=53
    access=localhost
    status=enabled
But no change here:

Code: [Select]

[root@mail ~]# dig default_.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 13208
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.wheatleylaw.com.      IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:24 2018
;; MSG SIZE  rcvd: 42

[root@mail ~]# dig _domainkey.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 37034
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.wheatleylaw.com.    IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:25 2018
;; MSG SIZE  rcvd: 44

[root@mail ~]# dig _dmarc.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 60349
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.wheatleylaw.com.                IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:26 2018
;; MSG SIZE  rcvd: 40

[root@mail ~]#
[root@mail ~]# dig default_.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 48268
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.gmail.com.            IN      TXT

;; Query time: 577 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:27 2018
;; MSG SIZE  rcvd: 36

[root@mail ~]# dig _domainkey.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 18544
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.gmail.com.          IN      TXT

;; Query time: 28 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:28 2018
;; MSG SIZE  rcvd: 38

[root@mail ~]# dig _dmarc.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 24782
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.gmail.com.              IN      TXT

;; ANSWER SECTION:
_dmarc.gmail.com.       600     IN      TXT     "v=DMARC1\; p=none\; sp=quarantine\; rua=mailto:mailauth-reports@google.com"

;; Query time: 74 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Fri Feb 16 15:44:29 2018
;; MSG SIZE  rcvd: 118
Saving from changing the DNS setting didn't mention needed a reconfigure, but does it?

[TAD2020]

Ran a reconfigure anyway (had to wait till after hours for the reboot), no change on the dig output or qpsmtpd logging.

Code: [Select]

@400000005a8785fb1cdfa3c4 2723 (mail) naughty: pass
@400000005a8785fb1ce4cffc 2723 250 <SCANNEREMAILADDRESS@wheatleylaw.com>, sender OK - how exciting to get mail from you!
@400000005a8785fb1cf2be64 2723 dispatching RCPT TO:<SOMEUSER@wheatleylaw.com>
@400000005a8785fb1d013584 2723 (rcpt) badrcptto: pass
@400000005a8785fb1d0344dc 2723 (rcpt) check_goodrcptto: stripping '-' extensions
@400000005a8785fb1e4050ec 2723 (rcpt) rcpt_ok: pass: wheatleylaw.com in rcpthosts
@400000005a8785fb1e420a54 2723 250 <SOMEUSER@wheatleylaw.com>, recipient ok
@400000005a8785fb1e4f6834 2723 dispatching DATA
@400000005a8785fb1e52330c 2723 354 go ahead
@400000005a8785fb1ea91154 2723 spooling message to disk
@400000005a87864b20c66f2c 2723 (data_post_headers) dkim: DNS query timeout for wheatleylaw.com
@400000005a87864b20c67314
@400000005a87864b20c6e074 2723 (data_post_headers) dkim: error, no signature, no policy
@400000005a87864b20c70784 2723 (data_post_headers) dkim: result: none
@400000005a87864b20d49ffc 2723 (data_post) bogus_bounce: pass, not a null sender
@400000005a87864b20ddeae4 2723 (data_post) headers: pass
@400000005a87864b20df2f1c 2723 (data_post) naughty: pass
@400000005a87864b21406da4 2723 (queue) logging::logterse: ` 192.168.1.231       Unknown [192.168.1.231] <SCANNEREMAILADDRESS@wheatleylaw.com>   <SOMEUSER@wheatleylaw.com>  queued          <20180216173055.0001.CanonTxNo.2054@[192.168.1.231]>
@400000005a87864b2156f344 2768 (queue) queue::qmail_2dqueue: (for 2723) Queuing to /var/qmail/bin/qmail-queue
@400000005a87864b220071e4 2723 250 Queued! 1518831169 qp 2768 <20180216173055.0001.CanonTxNo.2054@[192.168.1.231]>
@400000005a87864b22165b44 2723 dispatching QUIT
@400000005a87864b221a1c34 2723 221 wheatleylaw.com closing connection. Have a wonderful day.
@400000005a87864b221aef24 2723 click, disconnecting
@400000005a87864c17f333e4 1917 cleaning up after 2723
Looks like its using itself now at least.

Code: [Select]

[root@mail ~]# nslookup wheatleylaw.com
Server:         192.168.1.14
Address:        192.168.1.14#53

Non-authoritative answer:
Name:   wheatleylaw.com
Address: 192.168.1.14


[Jean-Philippe Pialasse]

please open a bug.
While it is not clear if this is a bug or a misconfiguration or an issue with the lan, it starts to be hard to help you on a the forum and follow all the logs in thread.

[TAD2020]

I'm not even sure what potential bug I should be reporting here, and I think it might be fixed now.

The Manage Domain DNS server field remaining populated appears to be a strange issue with Firefox 57's autocomplete (which still does this when the feature is disabled, and having never been populated with that entry in the first place). When checked with Chrome, server-manager properly shows that field as being blank. So this was a red herring.

resolv.conf still had an erroneous extra nameserver, but I figured out where that was coming from after generating a config report. For some reason, there was custom templates for resolv.conf that added it. I've removed those and regenerated from template, signal-event dns-update and reboot.
I never touched custom templates on this server, but if they are something that get backed up, then it was likely something carried over from the old server during the upgrade to 9.x 3 years ago. I don't know if I had ever touched custom templates on the old server, it dates back to to when 7.x was new, so far I cannot be sure of anything.

resolv.conf is finally correct:

Code: [Select]

[root@mail ~]# cat /etc/resolv.conf
#------------------------------------------------------------
#              !!DO NOT MODIFY THIS FILE!!
#
# Manual changes will be lost when this file is regenerated.
#
# Please read the developer's guide, which is available
# at http://www.contribs.org/development/
#
# Copyright (C) 1999-2006 Mitel Networks Corporation
#------------------------------------------------------------
domain wheatleylaw.com
nameserver 192.168.1.14

dnscache is also correct:

Code: [Select]

[root@mail ~]# db configuration show dnscache
dnscache=service
    TCPPort=53
    UDPPort=53
    access=private
    status=enabled

Still no change to the dig output.

Code: [Select]

[root@mail ~]# dig default_.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 47759
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.wheatleylaw.com.      IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 42

[root@mail ~]# dig _domainkey.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 36716
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.wheatleylaw.com.    IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 44

[root@mail ~]# dig _dmarc.wheatleylaw.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.wheatleylaw.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 53891
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.wheatleylaw.com.                IN      TXT

;; Query time: 0 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 40

[root@mail ~]#
[root@mail ~]# dig default_.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> default_.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NXDOMAIN, id: 39935
;; flags: qr aa rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;default_.gmail.com.            IN      TXT

;; Query time: 65 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 36

[root@mail ~]# dig _domainkey.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _domainkey.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 38886
;; flags: qr rd ra; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_domainkey.gmail.com.          IN      TXT

;; Query time: 73 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 38

[root@mail ~]# dig _dmarc.gmail.com TXT

; <<>> DiG 9.8.2rc1-RedHat-9.8.2-0.62.rc1.el6_9.5 <<>> _dmarc.gmail.com TXT
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 33021
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0

;; QUESTION SECTION:
;_dmarc.gmail.com.              IN      TXT

;; ANSWER SECTION:
_dmarc.gmail.com.       600     IN      TXT     "v=DMARC1\; p=none\; sp=quarantine\; rua=mailto:mailauth-reports@google.com"

;; Query time: 91 msec
;; SERVER: 192.168.1.14#53(192.168.1.14)
;; WHEN: Tue Feb 20 19:05:54 2018
;; MSG SIZE  rcvd: 118


However there appears to be no delay or errors in the qpsmtpd log now, and the couple of tests I've do so far have go through quickly like they used to.

Code: [Select]

2018-02-20 19:09:43.136206500 2518 Accepted connection 0/60 from 192.168.1.231 / pc-00231.wheatleylaw.com
2018-02-20 19:09:43.136379500 2518 Connection from pc-00231.wheatleylaw.com [192.168.1.231]
2018-02-20 19:09:43.302509500 2518 (connect) relay: skip, no match
2018-02-20 19:09:43.302749500 2518 220 mail.wheatleylaw.com ESMTP
2018-02-20 19:09:43.304048500 2518 dispatching HELO [192.168.1.231]
2018-02-20 19:09:43.304485500 2518 250 wheatleylaw.com Hi pc-00231.wheatleylaw.com [192.168.1.231]; I am so happy to meet you.
2018-02-20 19:09:43.305351500 2518 dispatching MAIL FROM:<SCANNEREMAILADDRESS@wheatleylaw.com>
2018-02-20 19:09:43.305975500 2518 (mail) naughty: pass
2018-02-20 19:09:43.306314500 2518 250 <SCANNEREMAILADDRESS@wheatleylaw.com>, sender OK - how exciting to get mail from you!
2018-02-20 19:09:43.307193500 2518 dispatching RCPT TO:<SOMEUSER@wheatleylaw.com>
2018-02-20 19:09:43.307793500 2518 (rcpt) badrcptto: pass
2018-02-20 19:09:43.307871500 2518 (rcpt) check_goodrcptto: stripping '-' extensions
2018-02-20 19:09:43.328123500 2518 (rcpt) rcpt_ok: pass: wheatleylaw.com in rcpthosts
2018-02-20 19:09:43.328297500 2518 250 <SOMEUSER@wheatleylaw.com>, recipient ok
2018-02-20 19:09:43.329171500 2518 dispatching DATA
2018-02-20 19:09:43.329360500 2518 354 go ahead
2018-02-20 19:09:43.335702500 2518 spooling message to disk
2018-02-20 19:09:43.424989500 2518 (data_post_headers) dkim: pass, no signature, neutral policy
2018-02-20 19:09:43.438930500 2518 (data_post) bogus_bounce: pass, not a null sender
2018-02-20 19:09:43.439588500 2518 (data_post) headers: pass
2018-02-20 19:09:43.439657500 2518 (data_post) naughty: pass
2018-02-20 19:09:43.461621500 2518 (queue) logging::logterse: ` 192.168.1.231 pc-00231.wheatleylaw.com [192.168.1.231] <SCANNEREMAILADDRESS@wheatleylaw.com> <SOMEUSER@wheatleylaw.com> queued <20180220190915.0001.CanonTxNo.2075@[192.168.1.231]>
2018-02-20 19:09:43.463108500 2519 (queue) queue::qmail_2dqueue: (for 2518) Queuing to /var/qmail/bin/qmail-queue
2018-02-20 19:09:43.476618500 2518 250 Queued! 1519182583 qp 2519 <20180220190915.0001.CanonTxNo.2075@[192.168.1.231]>
2018-02-20 19:09:43.478471500 2518 dispatching QUIT
2018-02-20 19:09:43.478804500 2518 221 wheatleylaw.com closing connection. Have a wonderful day.
2018-02-20 19:09:43.478877500 2518 click, disconnecting
2018-02-20 19:09:44.124882500 1821 cleaning up after 2518
Gonna monitor it more tomorrow.

[Jean-Philippe Pialasse]

Good to hear it works again.