Caught connection error in SMTP (localhost:1587) : <class 'ssl.SSLError'> with message: ac.robinson.email-oauth2-proxy

[brianjmurrell]

I frequently get:

2023-01-10 21:57:50: Caught connection error in SMTP (localhost:1587) : <class 'ssl.SSLError'> with message: ac.robinson.email-oauth2-proxy
2023-01-10 21:57:50: Is the server's `starttls` setting correct? Current value: True
2023-01-10 21:57:50: If you encounter this error repeatedly, please check that you have correctly configured python root certificates; see: https://github.com/simonrob/email-oauth2-proxy/issues/14

But this only happens a while after I have successfully authorized an O365 account and have successfully sent mail through it so it doesn't seem like it could/should be #14. And then a while later it might go back to being successful again, but then complaining again:

2023-01-10 22:06:44: SMTP (localhost:1587; [redacted]) [ Successfully authenticated SMTP connection - releasing session ]
2023-01-10 22:16:42: Caught connection error in SMTP (localhost:1587) : <class 'ssl.SSLError'> with message: ac.robinson.email-oauth2-proxy
2023-01-10 22:16:42: Is the server's `starttls` setting correct? Current value: True
2023-01-10 22:16:42: If you encounter this error repeatedly, please check that you have correctly configured python root certificates; see: https://github.com/simonrob/email-oauth2-proxy/issues/14

Any ideas?

[nbdd0121]

I got exactly this error yesterday. Changed MAX_SSL_HANDSHAKE_ATTEMPTS to 0 fixed the issue.

[simonrob]

Setting MAX_SSL_HANDSHAKE_ATTEMPTS removes the handshake timeout limit. Are you finding that the connection succeeds with a higher limit (i.e., the handshake is taking longer than expected), or are you perhaps just suppressing the error by doing this? (Add a log message after this line to find out).

I suspect this may be related to #118, though don't have any particular suggestions beyond the ones listed there as I cannot replicate this myself. If you can isolate the issue and find a way to replicate it reliably that would be really helpful.

[nbdd0121]

I wouldn't call MAX_SSL_HANDSHAKE_ATTEMPTS a timeout; it is incremented every time there's a read/write event. I believe read/write event can be repeated called if there is unconsumed data associated with the socket. So in a situation where e.g. the plain-text SMTP client sends data before handshake completes, the counter will quickly deplete due to unread data in the socket.

[simonrob]

It is not technically a timeout in that sense (it does not measure time as such), but it is used as a way to to abort connections where the SSL handshake seems to be failing. SMTP connections prior to STARTTLS shouldn't be affected because they are marked as an insecure connection until the STARTTLS command is received. Only reads/writes relating to the handshake are included when incrementing this counter.

[brianjmurrell]

Add a log message after this line to find out.

I have not set MAX_SSL_HANDSHAKE_ATTEMPTS to 0 as @nbdd0121 but I did add a log message as you suggested above, regardless.

When I get the error reported here, the log message is not printed.

But clearly I am still seeing this issue. Any further diagnosis I can do?

[simonrob]

It may just be that your particular SMTP configuration is requiring more negotiation to complete the handshake. I haven't seen anywhere near as many as 2^16 (65,536; the default maximum that is used as a way to abort failed attempts) calls to the handshake function during a successful attempt, but @nbdd0121 is correct that this value is the source of the error you are seeing. What happens if you increase MAX_SSL_HANDSHAKE_ATTEMPTS to, say, 2^17 or 2^18?

[brianjmurrell]

And/or we could just see how high the count could get. If I were to set it to say, 0 and then want to see what the count was when it was finally successful where would I put that Log? Would that go in the else: block or after

email-oauth2-proxy/emailproxy.py

Line 800 in a26edc6

self.socket.do_handshake()

?

[simonrob]

You could add the count (self.ssl_handshake_attempts) to the TLS handshake complete message a few lines below?

[brianjmurrell]

Interesting variation in counts:

2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 12125
2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 11479
2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 12109
2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 1
2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 1
2023-01-18 07:26:01: SMTP (localhost:1587) Attemps to complete SSL handshake: 1

[simonrob]

I would guess that the ~12k ones are during STARTTLS negotiation, and the subsequent one is in a send or recv that required additional data to be sent (which is normal – ssl.SSLWantReadError or ssl.SSLWantWriteError).

Regardless, these are all well below 65,536. What is the value when you get the error?

[brianjmurrell]

I just had one hit 68,010 and yet another at 67,473. Both were followed immediately by a value of 1.

[simonrob]

Seeing additional handshakes (the 1 and other low values) both straight after the initial handshake and also periodically after that is expected, but the current default maximum value was decided based solely on my own testing, and I'm perfectly happy to increase it.

Could you keep track of the values you get over a few days and suggest a new higher maximum?

[simonrob]

Reading through the other issue you have open, I realised that poor network connectivity might be part of the issue here – on a slow or unreliable connection, it could easily be possible for the handshake method to be called enough times to unintentionally pass the threshold. So, the issue-121 branch adds a 1ms delay each time this method returns in a "want read" or "want write" state. This should have essentially zero impact on fast connections, but does resolve the issue for me on simulated slower or intermittent networks.

Please could you try this branch?

[brianjmurrell]

Could you keep track of the values you get over a few days and suggest a new higher maximum?

Sure.

What exactly is it that is happening anywhere from 1 to over 64K times? Is it an operation that should only ever happen once under ideal conditions and that it takes over 64K times sometime is indicating some kind of resource constraint that requires sometimes over 64K attempts to finally succeed?