Incoming TLS/SSL with POP connections

[Reymouth]

Hello,

We are encountering errors with the POP Protocol and the implementation of TLS.
When receiving the mails, we always get the same error and the reception of the mails is slowed down.

The error links to issue 9, but I don't know if this is related and how to fix it.

Here are the errors below:

2022-07-29 10:15:57: Starting POP server at 0.0.0.0:1995 (TLS) proxying outlook.office365.com:995 (SSL/TLS)
2022-07-29 10:15:57: Initialised Email OAuth 2.0 Proxy - listening for authentication requests
2022-07-29 10:16:02: POP (0.0.0.0:1995) [ Successfully authenticated POP connection - removing proxy ]
2022-07-29 10:16:03: POP (0.0.0.0:1995) Warning: caught client-side SSL send error (see #9): SSLWantWriteError(3, 'The operation did not complete (write) (_ssl.c:2472)')
2022-07-29 10:16:04: POP (0.0.0.0:1995) Warning: caught client-side SSL send error (see #9): SSLWantWriteError(3, 'The operation did not complete (write) (_ssl.c:2472)')
2022-07-29 10:16:05: POP (0.0.0.0:1995) Warning: caught client-side SSL send error (see #9): SSLWantWriteError(3, 'The operation did not complete (write) (_ssl.c:2472)')

Thanks for your help.

[simonrob]

Thanks for reporting this – as you can see by the comments in #9, I've never been able to replicate this myself, and didn't receive a follow-up after the initial refinements made to the proxy, so haven't looked at it since.

Could you give any further detail about the particular setup you are using that causes this? For example, certificate type, SSL/TLS version/parameters etc?

[Reymouth]

Hello,
Here are the different elements that will allow you, I hope, to reproduce the malfunction.

System information below:

Debian 11
Kernel 5.10.127-1 (2022-06-30)
Python 3.9.2

We use a Let's Encrypt certificate generated with acme.sh using the command below:

acme.sh --issue --dns dns_gandi_livedns -d mydomain.fr
acme.sh --install-cert -d mydomain.fr --ca-file /opt/email-oauth2-proxy/ssl/mydomain.fr/chain.pem --cert-file /opt/email-oauth2-proxy/ssl/mydomain.fr/cert.pem --key-file /opt/email-oauth2-proxy/ssl/mydomain.fr/privkey.pem --fullchain-file /opt/email-oauth2-proxy/ssl/mydomain.fr/fullchain.pem --reloadcmd "systemctl restart emailproxy.service"

File emailproxy.config

[IMAP-1993]
local_address = 0.0.0.0
server_address = outlook.office365.com
server_port = 993
local_certificate_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/fullchain.pem
local_key_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/privkey.pem

[POP-1995]
local_address = 0.0.0.0
server_address = outlook.office365.com
server_port = 995
local_certificate_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/fullchain.pem
local_key_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/privkey.pem

[SMTP-1587]
local_address = 0.0.0.0
server_address = smtp.office365.com
server_port = 587
starttls = true
local_certificate_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/fullchain.pem
local_key_path = /opt/email-oauth2-proxy/ssl/mydomain.fr/privkey.pem

[IMAP-2993]
local_address = 0.0.0.0
server_address = imap.gmail.com
server_port = 993

[POP-2995]
local_address = 0.0.0.0
server_address = pop.gmail.com
server_port = 995

[SMTP-2465]
local_address = 0.0.0.0
server_address = smtp.gmail.com
server_port = 465

Client used to fetch emails from outside:

Thunderbird 91.11.0
POP3 (TLS) - 1995 / STMP (STARTTLS) - 1587

Thanks for your help.

[simonrob]

Thanks for the extra detail – this is really helpful.

I was able to replicate most of this setup, but still couldn't get the issue to trigger myself. However, I'm assuming that even though you are seeing this warning, the proxy is still working without issue. If that is indeed the case, then I'd suggest just shortening the proxy's wait time before retrying when this message is encountered (see line 689) – changing from 1 to, say, 0.01 would remove any noticeable delay in email receiving. If this change leads to the warning message being triggered annoyingly often, feel free to remove it.

Let me know how you get on – given that there seem to be no other adverse issues, I think that this warning should just be a debug message in future. I'm also happy to shorten the default wait/retry time if it doesn't cause any problems.

[simonrob]

Just to follow up: 7a3aa7c adds these changes – could you let me know if this resolves the issue?

[Reymouth]

I just implemented the suggested changes. I no longer have the message, but the script seems to freeze without an error message, preventing sending and receiving. I had already had this behavior previously with TLS in POP and SMTP.

To reproduce the behavior, I fetch the mails in POP several times and the script freezes a few minutes later.

Here are the last lines of the traces that I could take before the script freeze : https://paste.pichax.fr/wafewebovi.php

I remain available if you need other elements that can help resolve the malfunction

Thank's

[simonrob]

Thanks for the trace – this is really helpful. Please could you try cb9ac7b?

[Reymouth]

I just applied the patch and the script still freezes. The freeze may not be related to this issue.

New traces : https://paste.pichax.fr/eyanuwihob.lua

[simonrob]

This new trace ends at the SSL handshake, which the proxy doesn't have any involvement in (it just uses the built-in Python SSL library to wrap the socket).

Does the proxy work as expected when you don't use a local certificate?

[Reymouth]

The script works perfectly if I don't use local certificate. At the time of the freeze, the traces are exactly the same.

The configuration used is that of the comment above: #44 (comment)

[simonrob]

I had another look at this – there is very little python documentation about how to properly handle SSL/TLS handshakes and many examples seem conflicting (or have misunderstood, like I may also have done). Still, 76db1da moves the handshake to the client handler, which seems to be the recommendation – could you test this?

[Reymouth]

Thanks, the script no longer seems to freeze. However there are some errors when receiving or sending emails.

Without debug :

/usr/bin/python3 /opt/email-oauth2-proxy/emailproxy.py --local-server-auth --no-gui
2022-08-21 11:49:23: Initialising Email OAuth 2.0 Proxy from config file /opt/email-oauth2-proxy/emailproxy.config
2022-08-21 11:49:23: Starting IMAP server at 0.0.0.0:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2022-08-21 11:49:23: Starting POP server at 0.0.0.0:1995 (TLS) proxying outlook.office365.com:995 (SSL/TLS)
2022-08-21 11:49:23: Starting SMTP server at 0.0.0.0:1587 (TLS) proxying smtp.office365.com:587 (STARTTLS)
2022-08-21 11:49:23: Starting IMAP server at 0.0.0.0:2993 (unsecured) proxying imap.gmail.com:993 (SSL/TLS)
2022-08-21 11:49:23: Starting POP server at 0.0.0.0:2995 (unsecured) proxying pop.gmail.com:995 (SSL/TLS)
2022-08-21 11:49:23: Starting SMTP server at 0.0.0.0:2465 (unsecured) proxying smtp.gmail.com:465 (SSL/TLS)
2022-08-21 11:49:23: Initialised Email OAuth 2.0 Proxy - listening for authentication requests
2022-08-21 11:49:27: POP (0.0.0.0:1995) [ Successfully authenticated POP connection - removing proxy ]
2022-08-21 11:49:27: POP (0.0.0.0:1995) Caught asyncore info message (client) - error : uncaptured python exception, closing channel <main.POPOAuth2ClientConnection connected 81.254.169.207:61196 at 0x7efe10fd1b50> (<class 'ssl.SSLEOFError'>:EOF occurred in violation of protocol (_ssl.c:2622) [/usr/lib/python3.9/asyncore.py|read|83] [/usr/lib/python3.9/asyncore.py|handle_read_event|420] [/opt/email-oauth2-proxy/emailproxy.py|handle_read|634] [/usr/lib/python3.9/asyncore.py|recv|371] [/usr/lib/python3.9/ssl.py|recv|1226] [/usr/lib/python3.9/ssl.py|read|1101])
2022-08-21 11:50:09: SMTP (0.0.0.0:1587) [ Successfully authenticated SMTP connection - removing proxy ]
2022-08-21 11:50:12: SMTP (0.0.0.0:1587) Caught asyncore info message (client) - error : uncaptured python exception, closing channel <main.SMTPOAuth2ClientConnection connected 81.254.169.207:61246 at 0x7efe10fd1c70> (<class 'ssl.SSLEOFError'>:EOF occurred in violation of protocol (_ssl.c:2622) [/usr/lib/python3.9/asyncore.py|read|83] [/usr/lib/python3.9/asyncore.py|handle_read_event|420] [/opt/email-oauth2-proxy/emailproxy.py|handle_read|634] [/usr/lib/python3.9/asyncore.py|recv|371] [/usr/lib/python3.9/ssl.py|recv|1226] [/usr/lib/python3.9/ssl.py|read|1101])

With debug:
These errors flood enormously

2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 10.120.10.12:65294->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')
2022-08-21 11:48:50: POP (0.0.0.0:1995; 100.66.10.154:54196->outlook.office365.com:995) Caught client-side SSL recv error; retrying SSLWantReadError(2, 'The operation did not complete (read) (_ssl.c:1123)')

Traces : https://paste.pichax.fr/nikemejici.php

[simonrob]

Excellent!

The flood of debug messages was just from me trying to replicate; these will be be removed in the merged branch.

The other one is related to the addition of the suppress_ragged_eofs setting – it's unclear what the right value or response is here, but e529229 changes this – could you try?

[Reymouth]

Yeahhh, everything seems perfect now! Thank you for the corrections and your reactivity.