Frequent re-authorization requests

[brianjmurrell]

I frequently (seemingly daily, although that's not a scientific value) get requested to re-authorize my O365 SMTP connection with email-oauth2-proxy.

My email-oath2-proxy client is on a machine that connects to the corporate network by VPN, and the O365 servers through the corporate VPN. VPN connections are limited to something on the order of 12h per day. So every morning I [re-]connect my machine to the VPN and then 12h later I am disconnected until the next morning. So there is a period of about 12h where my client cannot reach the O365 servers.

It also appears that every morning I am also having to re-authorize email-oauth2-proxy, perhaps due to this lack of connectivity to O365 servers? But I do not have to do this same re-authorization with my Evolution EWS connection to O365 with it's OAuth2 token every morning. It seems to handle the 12h outage just fine and continues on with it's existing token once things are reconnected in the morning.

I should add that authorization to O365 happens (seemingly, but not really) passwordless due to having a Kerberos ticket.

So the question is, is having a network outage to O365 servers causing email-oath2-proxy to (incorrectly and) [overly-]aggressively discard what are actually valid tokens, leading to requesting the user to re-authorized much more frequently than necessary?

[simonrob]

The mention of passwordless suggests this is probably due to the proxy's default behaviour of requesting re-authentication if there is an invalid login attempt. I'd try changing delete_account_token_on_password_error to True (edit to fix typo: the value should be False to disable this behaviour) at the end of the config file.

[brianjmurrell]

I will try that.

Does emailproxy.py need restarting after I modify emailproxy.config to remove that or does it automatically pick up that change on the next re-auth (or some other event)?

If I do need to restart, how is that done when one has chosen to Start at login?

[simonrob]

There's an option in the menu (Reload configuration file), or alternatively you can send SIGHUP.

[brianjmurrell]

Ahh. Cool.

How do I restart it when Start at login is enabled, say, if I changed the code though?

[simonrob]

Restarting should work the same regardless of how you've started the proxy.

[brianjmurrell]

Restarting should work the same regardless of how you've started the proxy.

Is that to say that:

There's an option in the menu (Reload configuration file), or alternatively you can send SIGHUP.

actually restarts the proxy rather than the existing process just re-reading the config file?

If not, then I'm not quite following how I restart when I didn't start it the first place, but rather gnome-session started it as a startup app.

[simonrob]

I should have said "reloading" there, but as it happens, yes - reloading is pretty much equivalent to restarting. While it doesn't actually exit the script, it stops all servers first and then loads the config file rather than, say, diffing the old and new versions.

Fully restarting the script when auto-started after editing its source is pretty out of scope, but you could just exit then start manually - it would still restart at the next login (and in addition you could toggle the start at login option if you really wanted).

[brianjmurrell]

I'd try changing delete_account_token_on_password_error to True at the end of the config file.

Why True? That seems like the opposite of what I'd want given the name of the option, no?

In any case, I did try setting it to False (as it was already True when I reported this issue -- so setting it to True is certainly not a solution) and the token is still being deleted.

VPN connection went down at 22:54:34. email-oauth2-proxy's stdout/err after that time:

2023-01-17 23:00:05: Retrying login due to exception while requesting OAuth 2.0 credentials for [redacted]: InvalidToken(400, 'ac.robinson.email-oauth2-proxy')
2023-01-17 23:00:05: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:10:03: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:10:05: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:13:19: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:20:04: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:20:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:23:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:23:20: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:30:03: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:30:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:33:19: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:33:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:40:03: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:40:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:43:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:50:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-17 23:50:04: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-17 23:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:00:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:03:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:10:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:20:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:20:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:23:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:30:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:30:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:33:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:33:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:40:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:40:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:43:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:50:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:50:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 00:58:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:58:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 00:58:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:00:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:03:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:03:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:10:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:13:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:20:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:20:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:23:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:30:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:33:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:50:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:58:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:58:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 01:58:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:58:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 01:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:00:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:00:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:03:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:03:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:10:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:13:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:13:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:13:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:20:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:23:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:28:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:28:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:30:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:30:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:33:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:38:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:38:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:40:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:40:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:43:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:43:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:50:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 02:50:05: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:53:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 02:53:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:00:05: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:03:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:03:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:03:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:03:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:03:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:03:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:03:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:08:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:08:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:13:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:13:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:13:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:18:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:18:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:18:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:28:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:28:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:28:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:28:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:28:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:30:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:33:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:40:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:43:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:43:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:43:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:48:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:48:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:48:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 03:53:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:53:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 03:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:00:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:08:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:10:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:18:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:20:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:23:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:30:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:33:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:38:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:38:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:38:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:40:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:43:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:48:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:50:05: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:53:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:53:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 04:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 04:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:03:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:10:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:18:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:20:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:28:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:30:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:38:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:40:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:48:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 05:50:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 05:58:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:00:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:08:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:10:03: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:10:55: Authorisation request received for [redacted] (interactive mode)

(emailproxy.py:1134770): libappindicator-WARNING **: 06:11:45.806: Unable to connect to the Notification Watcher: Timeout was reached
2023-01-18 06:13:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:13:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:13:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:20:03: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:20:55: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:23:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:23:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:23:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:28:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:30:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:33:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:38:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:40:04: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:43:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:43:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:48:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:53:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:58:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:58:19: Authorisation request received for [redacted] (interactive mode)
2023-01-18 06:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 06:58:20: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 07:00:04: Authorisation request received for [redacted] (interactive mode)
2023-01-18 07:08:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 07:08:19: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 07:10:05: Authorisation result error for [redacted] - aborting login. Authorisation request timed out
2023-01-18 07:13:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 07:13:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 07:13:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 07:13:20: Authorisation request received for [redacted] (interactive mode)
2023-01-18 07:13:20: Authorisation request received for [redacted] (interactive mode)

And indeed there are no tokens in emailproxy.config which has a modification time of 23:00.

[simonrob]

Yes, that was a typo there – delete_account_token_on_password_error should be False to preserve the token after an invalid login attempt.

However, what you are actually getting here is a HTTP response code of 400 (Bad Request) from a token refresh call – see here. The token is always deleted in this case because it has expired (or is close to expiry) anyway. I would suggest enabling debug mode and looking at the content of the response that is printed when this happens – a message starting with Error refreshing access token; hopefully this will help narrow down what is going on.

[brianjmurrell]

However, what you are actually getting here is a HTTP response code of 400 (Bad Request) from a token refresh call

But why is that happening? The token was fetched less than 20h prior. Aren't tokens supposed to get renewed for much longer periods of time than that? My Evolution EWS OAuth token is renewed for days and days if not weeks. On the same machine that gets disconnected from the VPN every night.

This happened again last night. VPN disconnected at 23:19:29 and the proxy promptly reported 2023-01-18 23:20:04: Retrying login due to exception while requesting OAuth 2.0 credentials for [redacted]: InvalidToken(400, 'ac.robinson.email-oauth2-proxy'). That token was created less than 24h prior to that.

Is the token really invalid or is some kind of network error being mis-interpreted as a bad token issue?

[simonrob]

When you authorise your account two tokens are provided. One token allows access, and is typically short-lived; the other one is used to request additional access tokens when they expire (after a given validity period that is returned with the token response). It is this renewal of the access token that is failing in your case.

However, what you are actually getting here is a HTTP response code of 400 (Bad Request) from a token refresh call – see here. The token is always deleted in this case because it has expired (or is close to expiry) anyway. I would suggest enabling debug mode and looking at the content of the response that is printed when this happens – a message starting with Error refreshing access token; hopefully this will help narrow down what is going on.

Please try this and report back the error message you get in debug mode.

[brianjmurrell]

Here is what happens when the VPN is disconnected:

2023-01-19 23:30:03: New incoming connection to SMTP server at localhost:1587 (unsecured) proxying smtp.office365.com:587 (STARTTLS)
2023-01-19 23:30:03: Accepting new connection to SMTP server at localhost:1587 (unsecured) proxying smtp.office365.com:587 (STARTTLS) via ('127.0.0.1', 36722)
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) --> [ Client connected ]
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'220 YT4PR01CA0188.outlook.office365.com Microsoft ESMTP MAIL Service ready at Fri, 20 Jan 2023 04:30:03 +0000\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'220 YT4PR01CA0188.outlook.office365.com Microsoft ESMTP MAIL Service ready at Fri, 20 Jan 2023 04:30:03 +0000\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) --> b'EHLO laptop.gexample.com\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     --> b'EHLO laptop.gexample.com\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-YT4PR01CA0188.outlook.office365.com Hello [non-vpn-ip-address-redacted]\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-SIZE 157286400\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-PIPELINING\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-DSN\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-ENHANCEDSTATUSCODES\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-STARTTLS\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-8BITMIME\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-BINARYMIME\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-CHUNKING\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250 SMTPUTF8\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     --> b'STARTTLS\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'220 2.0.0 SMTP server ready\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-> [ Starting TLS handshake ]
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) [ Successfully negotiated SMTP STARTTLS connection - re-sending greeting ]
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     --> b'EHLO laptop.gexample.com\r\n'
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-> [ TLSv1.3 handshake complete ]
2023-01-19 23:30:03: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) Attempts to complete SSL handshake: 40
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-YT4PR01CA0188.outlook.office365.com Hello [non-vpn-ip-address-redacted]\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-YT4PR01CA0188.outlook.office365.com Hello [non-vpn-ip-address-redacted]\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-SIZE 157286400\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-SIZE 157286400\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-PIPELINING\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-PIPELINING\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-DSN\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-DSN\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-ENHANCEDSTATUSCODES\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-ENHANCEDSTATUSCODES\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-AUTH LOGIN XOAUTH2\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-AUTH PLAIN LOGIN\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-8BITMIME\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-8BITMIME\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-BINARYMIME\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-BINARYMIME\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250-CHUNKING\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250-CHUNKING\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'250 SMTPUTF8\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) <-- b'250 SMTPUTF8\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587) --> b'AUTH PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     --> b'AUTH XOAUTH2\r\n'
2023-01-19 23:30:04: SMTP (localhost:1587; 127.0.0.1:36722->smtp.office365.com:587)     <-- b'334 \r\n'
2023-01-19 23:30:04: Error refreshing access token - received invalid response: {'error': 'invalid_grant', 'error_description': 'AADSTS53003: Access has been blocked by Conditional Access policies. The access policy does not allow token issuance.\r\nTrace ID: [redacted]\r\nCorrelation ID: [redacted]\r\nTimestamp: 2023-01-20 04:30:04Z', 'error_codes': [53003], 'timestamp': '2023-01-20 04:30:04Z', 'trace_id': '[redacted]', 'correlation_id': '[redacted]', 'error_uri': 'https://login.microsoftonline.com/error?code=53003', 'suberror': 'message_only'}
2023-01-19 23:30:04: Retrying login due to exception while requesting OAuth 2.0 credentials for brian@example.com: InvalidToken(400, 'ac.robinson.email-oauth2-proxy')
2023-01-19 23:30:04: Authorisation request received for brian@example.com (interactive mode)

The invalid_grant issue happens because my company's IT department has told MS that they should only accept 0365 connections from our corporate network (which I am on when the VPN is connected) and refuse connections from the rest of the Internet.

So that invalid_grant is expected, but it's not really an invalid token and it should not be deleted in that case. It will work again once the machine is reconnected to the VPN and connections to O365 are once again being routed through the VPN and reaching MS from our company IP address.

This is how Evolution EWS operates, FWIW. It powers through the errors produced as a result of not talking to O365 from the corporate network (i.e. via the VPN).

[simonrob]

Thanks for following up with this detail. This is an interesting situation, because according to the OAuth 2.0 specification, invalid_grant means:

The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client.

The proxy doesn't currently check the error type, and assumes all of these errors will lead to requiring a new token. According to the specification this is a valid assumption, and indeed invalid_grant is the error type that is returned when the refresh token is invalid and does need reauthorisation.

I'm not really sure how it could differentiate between your temporary errors and real errors that both produce the same error type, and I'm not keen to add O365-specific error detection unless there is a clear need and consistent way of detecting and differentiating these. It would be much better if O365 returned a 401 request here really (which is also permitted by the specification).

You could fix this manually by removing the following two lines if you wanted, though that would mean that real refresh token expiry events wouldn't get caught. Alternatively, you could check for that specific error description and only skip raising the InvalidToken exception in that situation.

email-oauth2-proxy/emailproxy.py

Lines 715 to 716 in a26edc6

	if e.code == 400: # 400 Bad Request typically means re-authentication is required (refresh token expired)
	raise InvalidToken(e.code, APP_PACKAGE) from e

[brianjmurrell]

diff --git a/emailproxy.py b/emailproxy.py
index 1c88309..556df2e 100644
--- a/emailproxy.py
+++ b/emailproxy.py
@@ -701,7 +701,10 @@ class OAuth2Helper:
             e.message = json.loads(e.read())
             Log.debug('Error refreshing access token - received invalid response:', e.message)
             if e.code == 400:  # 400 Bad Request typically means re-authentication is required (refresh token expired)
-                raise InvalidToken(e.code, APP_PACKAGE) from e
+                # but not if due to client not accessing from a whitelisted IP address
+                if 'AADSTS53003' not in e.message['error_description']:
+                    Log.debug('Didn\'t find AADSTS53003 in:', e.message['error_description'])
+                    raise InvalidToken(e.code, APP_PACKAGE) from e
             raise e
 
     @staticmethod

does seem to do the trick.

[simonrob]

Yes – clearly it's possible to detect this particular error. But I'm reluctant to add specific O365 hacks, especially given the literally hundreds of different AADSTS error codes that can be generated.

Is there any other way to detect this error state?