Having trouble using an IMAP client that doesn't wait for server welcome message

[Schmass]

I'm using an IMAP client which isn't waiting for a welcome message from server. It just spits out its LOGIN command as first action.

This leads to the following behavior:

2022-11-26 19:37:59,081: Initialising Email OAuth 2.0 Proxy from config file /home/groupi/email-oauth2-proxy/emailproxy.config
2022-11-26 19:37:59,085: Starting IMAP server at localhost:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS)
2022-11-26 19:37:59,086: Starting POP server at localhost:2995 (unsecured) proxying pop.gmail.com:995 (SSL/TLS)
2022-11-26 19:37:59,088: Starting SMTP server at localhost:2465 (unsecured) proxying smtp.gmail.com:465 (SSL/TLS)
2022-11-26 19:37:59,090: Initialised Email OAuth 2.0 Proxy - listening for authentication requests. Connect your email client to begin
2022-11-26 19:38:39,835: New incoming connection to IMAP server at localhost:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS)
2022-11-26 19:38:39,835: Accepting new connection to IMAP server at localhost:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS) via ('127.0.0.1', 46232)
2022-11-26 19:38:39,849: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993) --> b'A1 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2022-11-26 19:38:40,115: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993)     --> b'A1 AUTHENTICATE XOAUTH2 '
2022-11-26 19:38:40,115: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993)     --> b'[[ Credentials removed from proxy log ]]'
2022-11-26 19:38:40,116: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993)     --> b'\r\n'
2022-11-26 19:38:40,116: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993; hans.xxx@gmail.com) --> [ Client connected ]
2022-11-26 19:38:40,117: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993; hans.xxx@gmail.com) <-> [ Starting TLS handshake ]
2022-11-26 19:38:40,140: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993; hans.xxx@gmail.com) Caught asyncore info message (server) - error : uncaptured python exception, closing channel <__main__.IMAPOAuth2ServerConnection connected imap.gmail.com:993 at 0x7fe4b6d6a400> (<class 'ssl.SSLError'>:[SSL: TLSV1_ALERT_PROTOCOL_VERSION] tlsv1 alert protocol version (_ssl.c:1056) [/usr/lib/python3.7/asyncore.py|read|83] [emailproxy.py|handle_read_event|801] [emailproxy.py|ssl_handshake|788] [/usr/lib/python3.7/ssl.py|do_handshake|1117])
2022-11-26 19:38:40,140: IMAP (localhost:2993; 127.0.0.1:46232->imap.gmail.com:993; hans.xxx@gmail.com) <-- [ Server disconnected ]

With two other clients everything is working perfectly fine:

2022-11-26 19:40:13,432: New incoming connection to IMAP server at localhost:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS)
2022-11-26 19:40:13,433: Accepting new connection to IMAP server at localhost:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS) via ('127.0.0.1', 41310)
2022-11-26 19:40:13,460: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) --> [ Client connected ]
2022-11-26 19:40:13,462: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) <-> [ Starting TLS handshake ]
2022-11-26 19:40:13,493: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) <-> [ TLS handshake complete ]
2022-11-26 19:40:13,518: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     <-- b'* OK Gimap ready for requests from XX.XXX.XX.XXX ...\r\n'
2022-11-26 19:40:13,519: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) <-- b'* OK Gimap ready for requests from XX.XXX.XX.XXX ...\r\n'
2022-11-26 19:40:13,521: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) --> b'EIIE0 CAPABILITY\r\n'
2022-11-26 19:40:13,522: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     --> b'EIIE0 CAPABILITY\r\n'
2022-11-26 19:40:13,548: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     <-- b'* CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 XYZZY SASL-IR AUTH=XOAUTH2 AUTH=PLAIN AUTH=PLAIN-CLIENTTOKEN AUTH=OAUTHBEARER AUTH=XOAUTH\r\n'
2022-11-26 19:40:13,551: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) <-- b'* CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 XYZZY SASL-IR AUTH=PLAIN\r\n'
2022-11-26 19:40:13,553: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     <-- b'EIIE0 OK Thats all she wrote! ...\r\n'
2022-11-26 19:40:13,553: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) <-- b'EIIE0 OK Thats all she wrote! ...\r\n'
2022-11-26 19:40:13,598: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993) --> b'EIIE1 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2022-11-26 19:40:13,798: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     --> b'EIIE1 AUTHENTICATE XOAUTH2 '
2022-11-26 19:40:13,798: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     --> b'[[ Credentials removed from proxy log ]]'
2022-11-26 19:40:13,799: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993)     --> b'\r\n'
2022-11-26 19:40:14,168: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993; hans.xxx@gmail.com)     <-- b'* CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH UTF8=ACCEPT LIST-EXTENDED LIST-STATUS LITERAL- SPECIAL-USE APPENDLIMIT=35651584\r\n'
2022-11-26 19:40:14,171: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993; hans.xxx@gmail.com) <-- b'* CAPABILITY IMAP4rev1 AUTH=PLAIN SASL-IR UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH UTF8=ACCEPT LIST-EXTENDED LIST-STATUS LITERAL- SPECIAL-USE APPENDLIMIT=35651584\r\n'
2022-11-26 19:40:14,172: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993; hans.xxx@gmail.com)     <-- b'EIIE1 OK hans.xxx@gmail.com authenticated (Success)\r\n'
2022-11-26 19:40:14,172: IMAP (localhost:2993; 127.0.0.1:41310->imap.gmail.com:993; hans.xxx@gmail.com) [ Successfully authenticated IMAP connection - releasing session ]

I'm running the proxy on Linux with no GUI:

python3 emailproxy.py --no-gui --local-server-auth --debug --log-file test.log

Is there a way to delay messages from the client until the TLS handshake with the server (Google in my case) is complete and the OK message from the server was received?
I think this should fix this issue.

By the way: This is a very useful project. Thank you for your effort to bring such thing to life.

[simonrob]

Thanks for reporting this.

Are both of your log examples from the same instance of the proxy, or are they running on different servers/containers?

The reason I ask is that it shouldn't matter if a client does something like this: the TLS handshake is handled separately, and in fact often needs a read or write to occur to complete. Normally TLSV1_ALERT_PROTOCOL_VERSION means a mismatch between the TLS versions supported by the remote server and your Python installation.

If these logs are both from the same instance of the proxy, please could you let me know what client this is from so that I can investigate?

[Schmass]

Both log examples are from the same instance of the proxy (even without restarting the proxy).
I thing the TLSV1_ALERT_PROTOCOL_VERSION error happens because the TLS channel is not ready yet.
My first thoughts also went in the direction of having a too old openSSL library. But I was surprised that Thinderbird and the python IMAP library as client worked flawlessly with the same proxy instance.
The error happens with unsecured and secured (SSL) access from my non working client ( old groupoffice version 6.2 ).

[simonrob]

Thanks for following up. I can replicate this with the following:

import socket
sock = socket.socket()
sock.connect(('localhost', 1995))
print('sent:', sock.send('A1 LOGIN [username] [password]\r\n'.encode('utf-8')), 'bytes')
print('received:', sock.recv(4096))
sock.close()

The reason that you get this particular error message is because handle_error doesn't currently treat TLSV1_ALERT_PROTOCOL_VERSION as an error it should suppress. That's an easy fix, of course.

Another approach would be to cache incoming messages until the connection is fully established. However, given that this does not match the IMAP specification, I'm reluctant to make any major changes to work around this. I also note that if you try this against, say, a STARTTLS server, you'll get the same result, with the client having to re-send the initial message because it is silently discarded.

[simonrob]

I'm going to close this issue as IMAP (or SMTP/POP) interactions that don't match the specification are not something that I intend to put much time into (except for, e.g., major clients that do this).