[bug]: SMTP broken when enabling proxy protocol via haproxy

[jimbojim]

What happened?

Following the documentation I enabled proxy protocol on haproxy. When I do this I get an SMTP connection error:

nc smtp.example.com 25
220 smtp.example.com Stalwart ESMTP at your service
500 5.5.1 Invalid command.
500 5.5.1 Invalid command.
500 5.5.1 Invalid command.
221 2.0.0 Bye.

How can we reproduce the problem?

Install stalwart in kubernetes.
Expose services via NodePort service.
Install haproxy to front end the NodePort service.
Enable proxy protocol in stalwart.
Connect to haproxy via nc on port 25.

kubectl get service stalwart-mail
stalwart-mail              NodePort    10.43.73.75     <none>        25:30756/TCP,465:31551/TCP,993:30577/TCP,4190:32418/TCP   2d3h

haproxy.cfg
frontend ft_smtp
    bind *:25
    mode tcp
    option tcplog
    default_backend bk_smtp

backend bk_smtp
    mode tcp
    server stalwart_mail_smtp_1 n1.example.com:30756 send-proxy-v2
    server stalwart_mail_smtp_2 n2.example.com:30756 send-proxy-v2
    server stalwart_mail_smtp_3 n3.example.com:30756 send-proxy-v2

cat etc/config.toml | grep proxy
server.proxy.trusted-networks = "10.0.0.0/8"

nc smtp.example.com 25
220 smtp.example.com Stalwart ESMTP at your service
500 5.5.1 Invalid command.
500 5.5.1 Invalid command.
500 5.5.1 Invalid command.
221 2.0.0 Bye.

Change haproxy to disable send-proxy-v2 and smtp works

backend bk_smtp
    mode tcp
    server stalwart_mail_smtp_1 n1.example.com:30756 
    server stalwart_mail_smtp_2 n2.example.com:30756 
    server stalwart_mail_smtp_3 n3.example.com:30756 

nc smtp.example.com 25
220 mail.example.com Stalwart ESMTP at your service
HELO example.com
250 mail.example.com you had me at HELO

Version

v0.9.x

What database are you using?

PostgreSQL

What blob storage are you using?

S3-compatible

Where is your directory located?

LDAP

What operating system are you using?

Docker

Relevant log output

No response

Code of Conduct

• I agree to follow this project's Code of Conduct

[mdecimus]

This is a configuration issue, the IP address range listed in server.proxy.trusted-networks might be incorrect. Find out what is the source IP address range of your reverse proxy.

[jimbojim]

Thanks for taking the time to respond. The ip of the haproxy server is 10.20.30.218/23. I added additional networks to the config for testing and the error persists.

server.proxy.trusted-networks.0 = "10.0.0.0/8"
server.proxy.trusted-networks.1 = "172.16.0.0/12"
server.proxy.trusted-networks.2 = "127.0.0.0/8"
server.proxy.trusted-networks.3 = "::1"

[jimbojim]

I captured a trace of the error as well from the stalwart server

2024-09-20T16:38:55Z INFO SMTP connection started (smtp.connection-start) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.transfer-limit", result = "Integer(262144000)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.duration", result = "Integer(600000)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.timeout", result = "Integer(300000)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "auth.spf.verify.ehlo", result = "Integer(2)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "auth.spf.verify.mail-from", result = "Integer(2)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "auth.iprev.verify", result = "Integer(2)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.ehlo.require", result = "Integer(1)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.ehlo.reject-non-fqdn", result = "Integer(1)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.directory", result = "Integer(0)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.directory", result = 
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.require", result = "Integer(0)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.errors.total", result = "Integer(3)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.errors.wait", result = "Integer(5000)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.auth.must-match-sender", result = "Integer(1)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.extensions.expn", result = "Integer(0)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.extensions.vrfy", result = "Integer(0)"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.connect.script", result = 
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "server.connect.hostname", result = "String("mail.domain.dev")"
2024-09-20T16:38:55Z TRACE Expression evaluation result (eval.result) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, id = "session.connect.greeting", result = "String("mail.domain.dev Stalwart ESMTP at your service")"
2024-09-20T16:38:55Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 54, contents = "220 mail.domain.dev Stalwart ESMTP at your service\r\n"
2024-09-20T16:38:55Z TRACE Raw SMTP input received (smtp.raw-input) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 28, contents = "\r\n\r\n\r\nQUIT\n!
                                                                                                                                                                                             \n\n\n���"
2024-09-20T16:38:55Z DEBUG Invalid command (smtp.invalid-command) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695
2024-09-20T16:38:55Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 28, contents = "500 5.5.1 Invalid command.\r\n"
2024-09-20T16:38:55Z DEBUG Invalid command (smtp.invalid-command) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695
2024-09-20T16:38:55Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 28, contents = "500 5.5.1 Invalid command.\r\n"
2024-09-20T16:38:55Z DEBUG Invalid command (smtp.invalid-command) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695
2024-09-20T16:38:55Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 28, contents = "500 5.5.1 Invalid command.\r\n"
2024-09-20T16:38:55Z DEBUG SMTP QUIT command (smtp.quit) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695
2024-09-20T16:38:55Z TRACE Raw SMTP output sent (smtp.raw-output) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, size = 16, contents = "221 2.0.0 Bye.\r\n"
2024-09-20T16:38:55Z INFO SMTP connection ended (smtp.connection-end) listenerId = "smtp", localPort = 25, remoteIp = 10.42.5.0, remotePort = 18695, elapsed = 0ms

[jimbojim]

I solved the issue. Not a bug, totally user error on my part.
Just in case some searches for this I want to post the solution. When you make changes to the proxy or listener settings you must restart the server, not just reload. I was making the change and reloading but the changes were not taking effect until I restarted the service.

[benbender]

@mdecimus I also fall into this "trap" and even if it's not a bug in a strictly technical sense, at least its a UX annoyance as the UI clearly doesn't work as one would expect. Maybe at least a note in the UI would be helpful…

[markus-seidl]

This cost me an hour of debugging - I would consider this a bug. Maybe add a message somewhere (even nothing in the docs!)