handle_DATA not called with Proxy Protocol

[ScottSturdivant]

Struggling to figure out how to receive messages when Proxy Protocol is enabled - any help would be greatly appreciated!

Simple code example:

#!/usr/bin/env python3
import time
import boto3
import logging
import sys
from aiosmtpd.controller import Controller


logger = logging.getLogger()
handler = logging.StreamHandler()
formatter = logging.Formatter(
        '%(asctime)s %(name)-12s %(levelname)-8s %(message)s')
handler.setFormatter(formatter)
logger.addHandler(handler)
logger.setLevel(logging.DEBUG)


class EmailForwarder:

    async def handle_PROXY(self, server, session, envelope, proxy_data):
        logger.debug(f'Proxy data: {proxy_data}')
        return True

    async def handle_DATA(self, server, session, envelope):
        logger.debug(f'server: {server}')
        logger.debug(f'session: {session}')
        logger.debug(f'envelope: {envelope}')
        logger.debug(f'raw: {envelope.original_content}')
        return '250 Message accepted for delivery'


if __name__ == '__main__':
    handler = EmailForwarder()
    controller = Controller(
        handler,
        hostname='0.0.0.0',
        port=10025,
        ready_timeout=10,
        proxy_protocol_timeout=5.0
    )

    # Run the event loop in a separate thread.
    try:
        controller.start()
        logger.info("Server is running")
    except:
        logger.exception("Failed to start server.")
        controller.stop()
        sys.exit(1)

    while True:
        time.sleep(60)

This service is running in Kubernetes, behind an AWS NLB (with proxy protocol enabled), and then an nginx-ingress. Nginx has been configured with and without proxy encoding/decoding. To send mail to this service, the following command is used:

echo "asdf" | mail -S smtp=mail.example.com:25 -s "Hello!" -v [email protected]

When nginx is NOT configured to decode the NLB proxy, I see the following in the logs:

2024-03-15 21:10:52,275 mail.log     INFO     ('10.41.52.189', 38894) handling connection
2024-03-15 21:10:52,275 mail.log     DEBUG    ('10.41.52.189', 38894) waiting PROXY handshake
2024-03-15 21:10:52,276 mail.debug   DEBUG    Waiting for PROXY signature
2024-03-15 21:10:52,276 mail.debug   DEBUG    PROXY version 2
2024-03-15 21:10:52,276 mail.debug   DEBUG    Waiting for PROXYv2 signature
2024-03-15 21:10:52,276 mail.debug   DEBUG    Got PROXYv2 signature
2024-03-15 21:10:52,276 mail.debug   DEBUG    Waiting for PROXYv2 Header
2024-03-15 21:10:52,276 mail.debug   DEBUG    Got PROXYv2 header
2024-03-15 21:10:52,277 mail.debug   DEBUG    Waiting for PROXYv2 tail part
2024-03-15 21:10:52,277 mail.debug   DEBUG    Got PROXYv2 tail part
2024-03-15 21:10:52,277 mail.log     INFO     ('10.41.52.189', 38894) valid PROXY handshake
2024-03-15 21:10:52,277 root         DEBUG    Proxy data: ProxyData(version=2, command=0, family=0, protocol=0, src_addr=None, dst_addr=None, src_port=None, dst_port=None, rest=bytearray(b'\x03\x00\x04\xa9\xb8~\x8f'), whole_raw=bytearray(b'\r\n\r\n\x00\r\nQUIT\n \x00\x00\x07\x03\x00\x04\xa9\xb8~\x8f'), tlv_start=None, error='', _tlv=None)
2024-03-15 21:10:52,277 mail.log     DEBUG    ('10.41.52.189', 38894) handle_PROXY returned True
2024-03-15 21:10:52,277 mail.log     DEBUG    ('10.41.52.189', 38894) << b'220 mail-relay Python SMTP 1.4.5'
2024-03-15 21:10:52,277 mail.log     INFO     ('10.41.52.189', 38894) EOF received
2024-03-15 21:10:52,278 mail.log     INFO     ('10.41.52.189', 38894) Connection lost during _handle_client()
2024-03-15 21:10:52,278 mail.log     INFO     ('10.41.52.189', 38894) connection lost

When nginx IS configured to decode the proxy protocol, there's a different yet still unsuccessful output:

2024-03-15 20:54:32,275 mail.log     INFO     ('10.41.52.189', 33840) handling connection
2024-03-15 20:54:32,275 mail.log     DEBUG    ('10.41.52.189', 33840) waiting PROXY handshake
2024-03-15 20:54:32,275 mail.debug   DEBUG    Waiting for PROXY signature
2024-03-15 20:54:32,275 mail.debug   DEBUG    PROXY version 1
2024-03-15 20:54:32,275 mail.debug   DEBUG    Get all PROXYv1 handshake
2024-03-15 20:54:32,275 mail.debug   DEBUG    Got PROXYv1 handshake
2024-03-15 20:54:32,275 mail.log     INFO     ('10.41.52.189', 33840) valid PROXY handshake
2024-03-15 20:54:32,275 root         DEBUG    Proxy data: ProxyData(version=1, command=None, family=<AF.INET: 1>, protocol=<PROTO.STREAM: 1>, src_addr=IPv4Address('10.41.58.120'), dst_addr=IPv4Address('10.41.52.189'), src_port=51628, dst_port=25, rest=b'', whole_raw=bytearray(b'PROXY TCP4 10.41.58.120 10.41.52.189 51628 25\r\n'), tlv_start=None, error='', _tlv=None)
2024-03-15 20:54:32,276 mail.log     DEBUG    ('10.41.52.189', 33840) handle_PROXY returned True
2024-03-15 20:54:32,276 mail.log     DEBUG    ('10.41.52.189', 33840) << b'220 mail-relay Python SMTP 1.4.5'
2024-03-15 20:54:32,276 mail.log     DEBUG    _handle_client readline: b'\r\n'
2024-03-15 20:54:32,276 mail.log     INFO     ('10.41.52.189', 33840) >> b''
2024-03-15 20:54:32,276 mail.log     DEBUG    ('10.41.52.189', 33840) << b'500 Error: bad syntax'
2024-03-15 20:54:32,276 mail.log     DEBUG    _handle_client readline: b'\r\n'
2024-03-15 20:54:32,276 mail.log     INFO     ('10.41.52.189', 33840) >> b''
2024-03-15 20:54:32,276 mail.log     DEBUG    ('10.41.52.189', 33840) << b'500 Error: bad syntax'
2024-03-15 20:54:32,276 mail.log     INFO     ('10.41.52.189', 33840) connection lost
2024-03-15 20:54:32,276 mail.log     INFO     ('10.41.52.189', 33840) Connection lost during _handle_client()

Finally, when proxy protocol is removed from all (my app, the NLB, and nginx), everything does work as expected.

Presumably it's the newline chars that are causing the problem, I just don't have a clue if it's something I'm doing wrong, or should work around (in the proxy handler?) or an issue with the proxy support?

Thanks for the info!