iprev lookup fails, with different resolvers, causing issues

[fyrk]

Hi,

I noticed that iprev doesn't seem to work on my instance of Stalwart Mail running in Docker.

The error message is either smtp::inbound::mail: context="iprev" event="lookup" result=temp error; DNS resolution error: request timed out ptr="" with resolver.type = "system", or smtp::inbound::mail: context="iprev" event="lookup" result=perm error; DNS record not found: Non-Existent Domain ptr="" with resolver.type = "cloudflare".

I'm not sure what is causing these issues, is this expected behaviour? If not, how can I debug this if it is not an issue with Stalwart Mail?

Thanks for any help!

Detailed logs

This is the part of the config that is likely relevant:

[resolver]
type = "system"
#preserve-intermediates = true
concurrency = 2
timeout = "5s"
attempts = 2
try-tcp-on-error = false

[resolver.cache]
txt = 2048
mx = 1024
ipv4 = 1024
ipv6 = 1024
ptr = 1024
tlsa = 1024
mta-sts = 1024

[auth.iprev]
verify = [
    { if = "listener", eq = "smtp", then = "relaxed" },
    { else = "disable" },
]

[auth.dnsbl]
verify = [
    { if = "listener", eq = "smtp", then = [
        "ip",
        "iprev",
        "ehlo",
        "return-path",
        "from",
    ] },
    { else = [
    ] },
]

[auth.dnsbl.lookup]
ip = ["zen.spamhaus.org", "bl.spamcop.net", "b.barracudacentral.org"]
domain = ["dbl.spamhaus.org"]

I made a few tests using ebay.com's password reset.

Using the above config produces this log:

[...]
2023-09-24T19:00:26.607215Z TRACE session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.181" remote.port=57846}: smtp::inbound::session: event="read" data="MAIL From:<[email protected]> SIZE=24492\r\n" size=38
2023-09-24T19:00:41.610284Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.181" remote.port=57846}: smtp::inbound::mail: context="iprev" event="lookup" result=temp error; DNS resolution error: request timed out ptr=""
2023-09-24T19:00:41.708136Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.181" remote.port=57846}: smtp::inbound::mail: context="spf" event="lookup" identity="mail-from" domain="mxphxpool1078.ebay.com" sender="[email protected]" result=Pass
2023-09-24T19:00:41.708216Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.181" remote.port=57846}: smtp::inbound::mail: context="mail-from" event="success" address="[email protected]"
2023-09-24T19:00:41.708343Z TRACE session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.181" remote.port=57846}: smtp::inbound::session: event="write" data="250 2.1.0 OK\r\n" size=14
[...]

The email gets delivered, but note the delay of 15 seconds.

Setting resolver.try-tcp-on-error = true causes a delay of 30s. Note how ebay.com seems to disconnect because of this, and the email is not delivered:

[...]
2023-09-24T19:03:40.414236Z TRACE session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::session: event="read" data="MAIL From:<[email protected]> SIZE=24493\r\n" size=38
2023-09-24T19:04:10.424155Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::mail: context="iprev" event="lookup" result=temp error; DNS resolution error: request timed out ptr=""
2023-09-24T19:04:10.490631Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::mail: context="spf" event="lookup" identity="mail-from" domain="mxphxpool1022.ebay.com" sender="[email protected]" result=Pass
2023-09-24T19:04:10.490670Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::mail: context="mail-from" event="success" address="[email protected]"
2023-09-24T19:04:10.490752Z TRACE session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::session: event="write" data="250 2.1.0 OK\r\n" size=14
2023-09-24T19:04:10.490775Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.184.88" remote.port=26981}: smtp::inbound::session: Failed to read from stream: Kind(UnexpectedEof) event="error"

If I use resolver.type = "cloudflare" instead, there is no delay, but the error message changes:

[...]
2023-09-24T19:08:47.004248Z TRACE session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.154" remote.port=37857}: smtp::inbound::session: event="read" data="MAIL From:<[email protected]> SIZE=24496\r\n" size=38
2023-09-24T19:08:47.366281Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.154" remote.port=37857}: smtp::inbound::mail: context="iprev" event="lookup" result=perm error; DNS record not found: Non-Existent Domain ptr=""
2023-09-24T19:08:47.394578Z DEBUG session{instance="smtp" protocol=Smtp remote.ip="::ffff:66.211.185.154" remote.port=37857}: smtp::inbound::ehlo: context="dnsbl" event="invalid-reply" query="ebay.com.dbl.spamhaus.org." reply=[127.255.255.254]

Also note that Reverse IP lookups on the Docker host work fine:

$ dig -x 66.211.184.88
88.184.211.66.in-addr.arpa. 3600 IN	PTR	mxphxpool1022.ebay.com.

[mdecimus]

Hi,

This has now been fixed, thanks for the report! The problem was that when binding to an IPv6 address, all remote IPv4 addresses are mapped to IPv6 (as you can see in your logs). The resolver was trying to lookup an IPv4 address as IPv6 which failed. This is probably a bug in the DNS libary but it was fixed in Stalwart by converting IPv6 mapped addresses back to IPv4.

The fix is now in the repository and this week or the next it will be included in the next release. In the meantime, if you do not have an IPv6 address on your server, you can fix this by binding all listeners to 0.0.0.0 instead if [::].

[fyrk]

In the meantime, if you do not have an IPv6 address on your server, you can fix this by binding all listeners to 0.0.0.0 instead if [::].

Thanks, that did it for now.