I’ve got a weird fail case that I’m unable to troubleshoot. I’m hoping someone here is familiar enough with the mailcow software suite to point me in right direction to continue troubleshooting and resolving this issue.
Problem
An outbound email (to: REDACTED@cfl.rr.com) cannot be delivered by my Mailcow server (aka mymail.com) because the recipient host pkvw-mx.msg.pkvw.co.charter.net cannot be resolved.
Software Info
I’m running dockerized mailcow, updated 2023-01-30 with its update.sh script, on Debian 10 (buster) VPS.
Investigation
Why charter.net?
It didn’t make sense that Mailcow would connect to charter.net to deliver mail for cfl.rr.com. To verify, I check the MX record. On the Debian host, I run…
root@mail:/opt/mailcow-dockerized# dig mx +short cfl.rr.com
10 pkvw-mx.msg.pkvw.co.charter.net.
And cfl.rr.com, indeed, uses ...charter.net for its mail service.
Can host resolve charter.net?
root@mail:/opt/mailcow-dockerized# dig +short pkvw-mx.msg.pkvw.co.charter.net
47.43.26.7
Yes, it can.
Can unbound container resolve charter.net?
root@mail:/opt/mailcow-dockerized# docker compose exec unbound-mailcow nslookup pkvw-mx.msg.pkvw.co.charter.net
Server: 127.0.0.11
Address: 127.0.0.11:53
Non-authoritative answer:
Name: pkvw-mx.msg.pkvw.co.charter.net
Address: 47.43.26.7
Non-authoritative answer:
With nslookup, the unbound container finds the IP address, but I think this query didn’t use the unbound service in the container. Let’s try again.
root@mail:/opt/mailcow-dockerized# docker compose exec unbound-mailcow unbound-control lookup pkvw-mx.msg.pkvw.co.charter.net
The following name servers are used for lookup of pkvw-mx.msg.pkvw.co.charter.net.
;rrset 83254 13 1 5 0
net. 83254 IN NS d.gtld-servers.net.
net. 83254 IN NS j.gtld-servers.net.
net. 83254 IN NS g.gtld-servers.net.
net. 83254 IN NS a.gtld-servers.net.
net. 83254 IN NS l.gtld-servers.net.
net. 83254 IN NS e.gtld-servers.net.
net. 83254 IN NS m.gtld-servers.net.
net. 83254 IN NS i.gtld-servers.net.
net. 83254 IN NS h.gtld-servers.net.
net. 83254 IN NS c.gtld-servers.net.
net. 83254 IN NS b.gtld-servers.net.
net. 83254 IN NS f.gtld-servers.net.
net. 83254 IN NS k.gtld-servers.net.
net. 83254 IN RRSIG NS 8 1 172800 20230205071256 20230129060256 27254 net. xF/rAvqjcsV0NGYI/7qG2KLBF3TPgxT82IDf6UdRUoIyeae/IE/Bz8JRhmAICRgCoxmoN70YNtghmlfUconmESaMU5YeEesyWvqXQQdLBh4cuUJ+Hc367W4EqgbRDOFy4iTSEX8Ud9Zm68ngKdlzTAE9qIazee+1/JKMVpRYqoTwCPTBqinamz6R/Jo4LK4smrcYBwzUy7uS14/4+MFxlQ== ;{id = 27254}
;rrset 9246 1 0 5 0
k.gtld-servers.net. 9246 IN A 192.52.178.30
;rrset 54390 1 0 1 0
k.gtld-servers.net. 54390 IN AAAA 2001:503:d2d::30
;rrset 37720 1 0 5 0
f.gtld-servers.net. 37720 IN A 192.35.51.30
;rrset 4698 1 0 1 0
f.gtld-servers.net. 4698 IN AAAA 2001:503:d414::30
;rrset 28264 1 0 5 0
b.gtld-servers.net. 28264 IN A 192.33.14.30
;rrset 4070 1 0 1 0
b.gtld-servers.net. 4070 IN AAAA 2001:503:231d::2:30
;rrset 45885 1 0 5 0
c.gtld-servers.net. 45885 IN A 192.26.92.30
;rrset 26852 1 0 1 0
c.gtld-servers.net. 26852 IN AAAA 2001:503:83eb::30
;rrset 41721 1 0 5 0
h.gtld-servers.net. 41721 IN A 192.54.112.30
;rrset 40041 1 0 1 0
h.gtld-servers.net. 40041 IN AAAA 2001:502:8cc::30
;rrset 48943 1 0 5 0
i.gtld-servers.net. 48943 IN A 192.43.172.30
;rrset 26852 1 0 1 0
i.gtld-servers.net. 26852 IN AAAA 2001:503:39c1::30
;rrset 31349 1 0 5 0
m.gtld-servers.net. 31349 IN A 192.55.83.30
;rrset 23327 1 0 1 0
m.gtld-servers.net. 23327 IN AAAA 2001:501:b1f9::30
;rrset 53274 1 0 5 0
e.gtld-servers.net. 53274 IN A 192.12.94.30
;rrset 22665 1 0 1 0
e.gtld-servers.net. 22665 IN AAAA 2001:502:1ca1::30
;rrset 5025 1 0 5 0
l.gtld-servers.net. 5025 IN A 192.41.162.30
;rrset 22006 1 0 1 0
l.gtld-servers.net. 22006 IN AAAA 2001:500:d937::30
;rrset 70297 1 0 5 0
a.gtld-servers.net. 70297 IN A 192.5.6.30
;rrset 81225 1 0 1 0
a.gtld-servers.net. 81225 IN AAAA 2001:503:a83e::2:30
;rrset 1680 1 0 5 0
g.gtld-servers.net. 1680 IN A 192.42.93.30
;rrset 14486 1 0 1 0
g.gtld-servers.net. 14486 IN AAAA 2001:503:eea3::30
;rrset 25122 1 0 5 0
j.gtld-servers.net. 25122 IN A 192.48.79.30
;rrset 3893 1 0 1 0
j.gtld-servers.net. 3893 IN AAAA 2001:502:7094::30
;rrset 44982 1 0 5 0
d.gtld-servers.net. 44982 IN A 192.31.80.30
;rrset 53947 1 0 1 0
d.gtld-servers.net. 53947 IN AAAA 2001:500:856e::30
Delegation with 13 names, of which 0 can be examined to query further addresses.
It provides 26 IP addresses.
2001:500:856e::30 not in infra cache.
192.31.80.30 NoAuthButRecursive rto 310 msec, ttl 214, ping 2 var 77 rtt 310, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:502:7094::30 not in infra cache.
192.48.79.30 NoAuthButRecursive rto 338 msec, ttl 214, ping 26 var 78 rtt 338, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:eea3::30 not in infra cache.
192.42.93.30 NoAuthButRecursive rto 306 msec, ttl 214, ping 2 var 76 rtt 306, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:a83e::2:30 not in infra cache.
192.5.6.30 NoAuthButRecursive rto 228 msec, ttl 214, ping 8 var 55 rtt 228, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:500:d937::30 not in infra cache.
192.41.162.30 NoAuthButRecursive rto 266 msec, ttl 214, ping 6 var 65 rtt 266, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:502:1ca1::30 not in infra cache.
192.12.94.30 NoAuthButRecursive rto 306 msec, ttl 214, ping 2 var 76 rtt 306, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:501:b1f9::30 not in infra cache.
192.55.83.30 NoAuthButRecursive rto 214 msec, ttl 214, ping 6 var 52 rtt 214, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:39c1::30 not in infra cache.
192.43.172.30 NoAuthButRecursive rto 306 msec, ttl 214, ping 2 var 76 rtt 306, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:502:8cc::30 not in infra cache.
192.54.112.30 not in infra cache.
2001:503:83eb::30 not in infra cache.
192.26.92.30 NoAuthButRecursive rto 310 msec, ttl 214, ping 2 var 77 rtt 310, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:231d::2:30 not in infra cache.
192.33.14.30 NoAuthButRecursive rto 261 msec, ttl 214, ping 5 var 64 rtt 261, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:d414::30 not in infra cache.
192.35.51.30 NoAuthButRecursive rto 271 msec, ttl 504, ping 7 var 66 rtt 271, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
2001:503:d2d::30 not in infra cache.
192.52.178.30 NoAuthButRecursive rto 367 msec, ttl 214, ping 23 var 86 rtt 367, tA 0, tAAAA 0, tother 0, EDNS 0 probed.
And no, unbound appears unable to resolve the domain pkvw-mx.msg.pkvw.co.charter.net.
However, unbound-control lookup resolves just fine for other domains I try (e.g. gmail.com, yahoo.com, etc).
Do the unbound logs provide more info?
Not with the default settings they don’t. And even with more verbosity, using unbound-control lookup just drops a single log entry that command lookup <query> occurred with no further debugging info.
Best attempt at unbound log debugging…
So let’s amp up the unbound log verbosity. docker compose exec unbound-mailcow unbound-control verbosity 3.
And perform a lookup from the postfix container, which does produce verbose log entries in the unbound log. docker compose exec postfix-mailcow nslookup pkvw-mx.msg.pkvw.co.charter.net.
And the log output for that query is…
[1675369747] unbound[1:0] info: 172.22.1.253 pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_new
[1675369747] unbound[1:0] info: validator operate: query pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1675369747] unbound[1:0] info: resolving pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: resolving (init part 2): pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: resolving (init part 3): pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: processQueryTargets: pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: removing 4 labels
[1675369747] unbound[1:0] info: processQueryTargets: pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: removing 3 labels
[1675369747] unbound[1:0] info: sending query: co.charter.net. A IN
[1675369747] unbound[1:0] debug: sending to target: <net.> 192.55.83.30#53
[1675369747] unbound[1:0] debug: cache memory msg=4086245 rrset=4455827 infra=1949236 val=1498100
[1675369747] unbound[1:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1675369747] unbound[1:0] info: iterator operate: query pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: response for pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: reply from <net.> 192.55.83.30#53
[1675369747] unbound[1:0] info: query response was NXDOMAIN ANSWER
[1675369747] unbound[1:0] info: finishing processing for pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1675369747] unbound[1:0] info: validator operate: query pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] debug: validator[module 0] operate: extstate:module_state_initial event:module_event_pass
[1675369747] unbound[1:0] info: validator operate: query charter.net. DS IN
[1675369747] unbound[1:0] debug: iterator[module 1] operate: extstate:module_state_initial event:module_event_pass
[1675369747] unbound[1:0] info: resolving charter.net. DS IN
[1675369747] unbound[1:0] info: resolving (init part 2): charter.net. DS IN
[1675369747] unbound[1:0] info: resolving (init part 3): charter.net. DS IN
[1675369747] unbound[1:0] info: processQueryTargets: charter.net. DS IN
[1675369747] unbound[1:0] info: sending query: charter.net. DS IN
[1675369747] unbound[1:0] debug: sending to target: <net.> 192.35.51.30#53
[1675369747] unbound[1:0] debug: cache memory msg=4086245 rrset=4455827 infra=1949236 val=1498100
[1675369747] unbound[1:0] debug: iterator[module 1] operate: extstate:module_wait_reply event:module_event_reply
[1675369747] unbound[1:0] info: iterator operate: query charter.net. DS IN
[1675369747] unbound[1:0] info: response for charter.net. DS IN
[1675369747] unbound[1:0] info: reply from <net.> 192.35.51.30#53
[1675369747] unbound[1:0] info: query response was nodata ANSWER
[1675369747] unbound[1:0] info: finishing processing for charter.net. DS IN
[1675369747] unbound[1:0] debug: validator[module 0] operate: extstate:module_wait_module event:module_event_moddone
[1675369747] unbound[1:0] info: validator operate: query charter.net. DS IN
[1675369747] unbound[1:0] info: NSEC3s for the referral proved no DS.
[1675369747] unbound[1:0] debug: validator[module 0] operate: extstate:module_wait_subquery event:module_event_pass
[1675369747] unbound[1:0] info: validator operate: query pkvw-mx.msg.pkvw.co.charter.net. A IN
[1675369747] unbound[1:0] info: Verified that unsigned response is INSECURE
[1675369747] unbound[1:0] debug: cache memory msg=4086245 rrset=4455827 infra=1949236 val=1498100
There’s a lot of noise in there. Best I can figure is unbound tries to lookup co.charter.net first, and found NXDOMAIN…
info: sending query: co.charter.net. A IN
info: query response was NXDOMAIN ANSWER
So then it tried to lookup charter.net and found “nodata ANSWER”?. I don’t know what this response means, but no IP is mentioned after that, nor any further attempts to resolve.
Where do I go from here?
Is this is a DNSsec issue since the logs mention “response is INSECURE”, and I just need to relax the DNSsec configuration?
Is there some method for retrieving clues I’ve overlooked and need to try?