search

simonrob / email-oauth2-proxy

An IMAP/POP/SMTP proxy that transparently adds OAuth 2.0 authentication for email clients that don't support this method.
Apache License 2.0
794 stars 85 forks source link

Proxy asks for authorisation every few hours with an InvalidToken() message in the logs #183

Closed Draykan closed 1 year ago

Draykan commented 1 year ago

I'm using Email OAuth 2.0 Proxy to access Office 365 mailboxes with IMAP using Apple Mail on Mac. I have a single Mac where the proxy keeps asking to reauthorise the configured IMAP accounts after an indefinite amount of time that may span from 20 hours to a day and a half.

The weird thing is that I have configured the same IMAP accounts using the same Office 365 access account on another Mac and I'm not having any problems with it. The only differences between the two Macs I am aware of are the hardware model and the macOS Ventura version installed.

Working Mac details: • MacBook Air (M1, 2020) • macOS Ventura 13.5 (22G5072a) Beta 5

Non-working Mac details: • MacBook Air (M2, 2022) • macOS Ventura 13.4 (22F66)

Both the Macs are using Python 3.9.6 from the installed Command Line Tools for Xcode 14.3.1 package and the same Email OAuth 2.0 Proxy 2023-05-18 version. I've also aligned the versions of all the Python projects installed on the two machines (i.e. the output of python3 -m pip list is exactly the same):

Package                              Version
------------------------------------ -------
altgraph                             0.17.2
bottle                               0.12.25
cffi                                 1.15.1
cryptography                         41.0.1
future                               0.18.2
macholib                             1.15.2
Pillow                               9.5.0
pip                                  23.1.2
prompt-toolkit                       3.0.38
proxy-tools                          0.1.0
pycparser                            2.21
pyobjc-core                          9.2
pyobjc-framework-Cocoa               9.2
pyobjc-framework-Quartz              9.2
pyobjc-framework-Security            9.2
pyobjc-framework-SystemConfiguration 9.2
pyobjc-framework-WebKit              9.2
pyoslog                              1.1.0
pystray                              0.19.4
pywebview                            4.2.2
setuptools                           58.0.4
six                                  1.15.0
timeago                              1.0.16
typing_extensions                    4.6.3
wcwidth                              0.2.6
wheel                                0.37.0

In Apple Mail on the affected machine I disabled all the proxied IMAP accounts except one and ran the script with the --debug and --log-file options. This is what I see in the logs file when the Proxy asks to reauthorise that IMAP account (I redacted the real e-mail address):

[…]
2023-07-11 07:30:39,434: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3162 FETCH (FLAGS (\\Seen) UID 13831)\r\n* 3163 FETCH (FLAGS (\\Seen) UID 13835)\r\n* 3164 FETCH (FLAGS (\\Seen) UID 13838)\r\n* 3165 FETCH (FLAGS (\\Seen) UID 13839)\r\n* 3166 FETCH (FLAGS (\\Seen) UID 13840)\r\n* 3167 FETCH (FLAGS (\\Seen) UID 13847)\r\n* 3168 FETCH (FLAGS (\\Seen) UID 13850)\r\n* 3169 FETCH (FLAGS () UID 13852)\r\n* 3170 FETCH (FLAGS () UID 13855)\r\n* 3171 FETCH (FLAGS () UID 13858)\r\n* 3172 FETCH (FLAGS () UID 13859)\r\n47.80 OK FETCH completed.\r\n'
2023-07-11 07:30:39,458: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) --> b'48.80 IDLE\r\n'
2023-07-11 07:30:39,504: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) <-- b'+ IDLE accepted, awaiting DONE command.\r\n'
2023-07-11 07:56:42,457: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) --> b'DONE\r\n'
2023-07-11 07:56:42,500: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* BYE Session invalidated - AccessTokenExpired\r\n'
2023-07-11 07:56:42,501: IMAP (localhost:1993; ::1:58314->outlook.office365.com:993; redacted_email@domain.ext) --> b'89.82 NOOP\r\n'
2023-07-11 07:56:42,509: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-11 07:56:42,510: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-11 07:56:42,543: IMAP (localhost:1993; ::1:58314->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* BYE Session invalidated - AccessTokenExpired\r\n'
2023-07-11 07:56:42,547: IMAP (localhost:1993; ::1:58314->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-11 07:56:42,547: IMAP (localhost:1993; ::1:58314->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-11 07:57:39,773: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-11 07:57:39,774: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 58537, 0, 0)
2023-07-11 07:57:39,802: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) --> [ Client connected ]
2023-07-11 07:57:39,813: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-11 07:57:39,856: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-11 07:57:39,869: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADIAUAAyADYANABDAEEAMAAwADMAMAAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-11 07:57:39,870: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADIAUAAyADYANABDAEEAMAAwADMAMAAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-11 07:57:39,871: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) --> b'1.85 CAPABILITY\r\n'
2023-07-11 07:57:39,871: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     --> b'1.85 CAPABILITY\r\n'
2023-07-11 07:57:39,885: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-11 07:57:39,886: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-11 07:57:39,886: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     <-- b'1.85 OK CAPABILITY completed.\r\n'
2023-07-11 07:57:39,886: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'1.85 OK CAPABILITY completed.\r\n'
2023-07-11 07:57:39,886: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) --> b'2.85 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-11 07:57:39,887: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     --> b'2.85 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-11 07:57:39,901: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-11 07:57:39,901: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-11 07:57:39,901: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993)     <-- b'2.85 OK ID completed\r\n'
2023-07-11 07:57:39,902: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'2.85 OK ID completed\r\n'
2023-07-11 07:57:39,902: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) --> b'4.85 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-11 07:57:59,312: Caught exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: ConnectionResetError(54, 'Connection reset by peer')
2023-07-11 07:57:59,314: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'4.85 NO AUTHENTICATE Email OAuth 2.0 Proxy: Login failed for account redacted_email@domain.ext - please check your internet connection and retry\r\n'
2023-07-11 07:57:59,314: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- b'* BYE Autologout; authentication failed\r\n'
2023-07-11 07:57:59,314: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) --> [ Client disconnected ]
2023-07-11 07:57:59,315: IMAP (localhost:1993; ::1:58537->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-11 07:57:59,317: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-11 07:57:59,317: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 58544, 0, 0)
2023-07-11 07:57:59,341: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) --> [ Client connected ]
2023-07-11 07:57:59,347: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-11 07:57:59,386: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-11 07:57:59,400: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAwADIAOQAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-11 07:57:59,400: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAwADIAOQAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-11 07:57:59,401: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) --> b'1.86 CAPABILITY\r\n'
2023-07-11 07:57:59,401: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993)     --> b'1.86 CAPABILITY\r\n'
2023-07-11 07:57:59,414: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-11 07:57:59,415: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-11 07:57:59,415: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993)     <-- b'1.86 OK CAPABILITY completed.\r\n'
2023-07-11 07:57:59,415: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) <-- b'1.86 OK CAPABILITY completed.\r\n'
2023-07-11 07:57:59,415: IMAP (localhost:1993; ::1:58544->outlook.office365.com:993) --> b'2.86 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-11 07:57:59,473: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-11 07:57:59,523: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-11 08:03:57,304: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-11 08:03:57,304: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 58553, 0, 0)
2023-07-11 08:03:57,764: IMAP (localhost:1993; ::1:58553->outlook.office365.com:993) --> [ Client connected ]
2023-07-11 08:03:57,773: IMAP (localhost:1993; ::1:58553->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-11 08:03:57,812: IMAP (localhost:1993; ::1:58553->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-11 08:03:57,825: IMAP (localhost:1993; ::1:58553->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAyADEAMwAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-11 08:03:57,826: IMAP (localhost:1993; ::1:58553->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAyADEAMwAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
[…]

It seems to me that the relevant line is: 2023-07-11 07:57:59,473: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()

However, I'm failing to find out why the token has been invalidated and I don't know how to troubleshoot the problem further. Do you have any suggestions? Thank you.

simonrob commented 1 year ago

This is an good find – while you're correct that the re-authorisation request is triggered at the line you quoted, the actual root cause is earlier, when the O365 server gives this message:

2023-07-11 07:56:42,500: IMAP (localhost:1993; ::1:58310->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* BYE Session invalidated - AccessTokenExpired\r\n'

I think your client is probably keeping the same connection open for longer than the expiry limit for a single token, and because of this the proxy isn't making an automatic refresh request. I suspect this issue will go away if you restart your client (or the proxy), say, once every hour or so.

The proxy doesn't currently handle this case – i.e., where access tokens are initially valid but later expire (or are prematurely invalidated) during the course of a single long-running connection at the end of which the refresh token is still valid. Presumably your O365 account is set to use relatively short-lived tokens, and there is a difference in client connection behaviour between the two versions you are using.

Please could you try the version in branch issue-183 and let me know whether you are still prompted to re-authorise repeatedly?

Draykan commented 1 year ago

Hi Simon, thank you, I tried the version in branch issue-183 but unfortunately after 15/16 hours it still asked to reauthorise the IMAP account again.

This is a snippet of the new debug log, please tell me if you need to see more of it:

2023-07-14 09:36:13,356: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) <-- b'9.1200 OK FETCH completed.\r\n'
2023-07-14 09:36:13,357: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) --> b'10.1200 UID FETCH 13994 BODY.PEEK[]<6256.15736>\r\n'
2023-07-14 09:36:13,358: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) --> b'11.1200 UID FETCH 13991 BODY.PEEK[]<24210.29455>\r\n'
2023-07-14 09:36:13,620: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3197 FETCH (BODY[]<6256> {0}\r\n UID 13994)\r\n'
2023-07-14 09:36:13,675: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) <-- b'10.1200 OK FETCH completed.\r\n'
2023-07-14 09:36:13,675: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3196 FETCH (BODY[]<24210> {0}\r\n UID 13991)\r\n11.1200 OK FETCH completed.\r\n'
2023-07-14 09:36:13,681: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) --> b'12.1200 IDLE\r\n'
2023-07-14 09:36:13,906: IMAP (localhost:1993; ::1:64153->outlook.office365.com:993; redacted_email@domain.ext) <-- b'+ IDLE accepted, awaiting DONE command.\r\n'
2023-07-14 09:36:13,907: IMAP (localhost:1993; ::1:64174->outlook.office365.com:993; redacted_email@domain.ext) --> b'6.1202 LOGOUT\r\n'
2023-07-14 09:36:13,908: IMAP (localhost:1993; ::1:64174->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-14 09:36:13,910: IMAP (localhost:1993; ::1:64174->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 09:39:07,542: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 09:39:07,543: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 64189, 0, 0)
2023-07-14 09:39:07,687: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 09:39:07,695: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 09:39:07,917: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 09:39:07,936: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAwADQANgAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:39:07,937: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [TQBSADEAUAAyADYANABDAEEAMAAwADQANgAuAEYAUgBBAFAAMgA2ADQALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:39:07,938: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) --> b'1.1207 CAPABILITY\r\n'
2023-07-14 09:39:07,938: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     --> b'1.1207 CAPABILITY\r\n'
2023-07-14 09:39:08,079: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:39:08,079: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:39:08,079: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     <-- b'1.1207 OK CAPABILITY completed.\r\n'
2023-07-14 09:39:08,080: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- b'1.1207 OK CAPABILITY completed.\r\n'
2023-07-14 09:39:08,080: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) --> b'2.1207 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-14 09:39:08,081: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     --> b'2.1207 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-14 09:39:08,141: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 09:39:08,141: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 09:39:08,141: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     <-- b'2.1207 OK ID completed\r\n'
2023-07-14 09:39:08,141: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- b'2.1207 OK ID completed\r\n'
2023-07-14 09:39:08,143: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) --> b'4.1207 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:45:00,709: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     --> b'4.1207 AUTHENTICATE XOAUTH2 '
2023-07-14 09:45:00,710: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993)     --> b'[[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:45:05,412: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-14 09:45:05,415: IMAP (localhost:1993; ::1:64189->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 09:45:05,415: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 09:45:05,415: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 64226, 0, 0)
2023-07-14 09:45:13,443: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 09:45:13,454: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 09:45:18,461: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 09:45:18,491: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAOAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:45:18,492: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAOAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:45:18,493: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) --> b'1.1210 CAPABILITY\r\n'
2023-07-14 09:45:18,493: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     --> b'1.1210 CAPABILITY\r\n'
2023-07-14 09:45:20,853: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:45:20,854: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:45:20,854: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     <-- b'1.1210 OK CAPABILITY completed.\r\n'
2023-07-14 09:45:20,854: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-- b'1.1210 OK CAPABILITY completed.\r\n'
2023-07-14 09:45:20,855: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) --> b'2.1210 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:45:20,936: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     --> b'2.1210 AUTHENTICATE XOAUTH2 '
2023-07-14 09:45:20,936: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993)     --> b'[[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:46:37,198: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-14 09:46:37,203: IMAP (localhost:1993; ::1:64226->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 09:46:37,203: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 09:46:37,203: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 64286, 0, 0)
2023-07-14 09:46:38,012: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 09:46:38,022: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 09:46:38,210: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 09:46:38,226: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAMAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:46:38,227: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAMAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:46:38,228: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) --> b'1.1213 CAPABILITY\r\n'
2023-07-14 09:46:38,228: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993)     --> b'1.1213 CAPABILITY\r\n'
2023-07-14 09:46:38,240: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:46:38,241: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:46:38,241: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993)     <-- b'1.1213 OK CAPABILITY completed.\r\n'
2023-07-14 09:46:38,241: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) <-- b'1.1213 OK CAPABILITY completed.\r\n'
2023-07-14 09:46:38,241: IMAP (localhost:1993; ::1:64286->outlook.office365.com:993) --> b'2.1213 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:46:38,309: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 09:46:38,357: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 09:46:38,404: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 09:48:18,365: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 09:48:18,367: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 64293, 0, 0)
2023-07-14 09:48:18,382: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 09:48:18,391: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 09:48:18,478: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 09:48:18,488: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:48:18,488: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 09:48:18,490: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) --> b'1.1214 CAPABILITY\r\n'
2023-07-14 09:48:18,490: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     --> b'1.1214 CAPABILITY\r\n'
2023-07-14 09:48:18,502: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:48:18,502: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 09:48:18,503: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     <-- b'1.1214 OK CAPABILITY completed.\r\n'
2023-07-14 09:48:18,503: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-- b'1.1214 OK CAPABILITY completed.\r\n'
2023-07-14 09:48:18,504: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) --> b'2.1214 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-14 09:48:18,504: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     --> b'2.1214 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4 (22F66)" "vendor" "Apple Inc.")\r\n'
2023-07-14 09:48:18,516: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 09:48:18,516: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 09:48:18,516: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993)     <-- b'2.1214 OK ID completed\r\n'
2023-07-14 09:48:18,517: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) <-- b'2.1214 OK ID completed\r\n'
2023-07-14 09:48:18,518: IMAP (localhost:1993; ::1:64293->outlook.office365.com:993) --> b'4.1214 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 09:48:18,588: Authorisation request received for redacted_email@domain.ext (interactive mode)

I've also updated the affected Mac to macOS 13.4.1 and started the proxy in debug mode again, I will post the updated logs if/when it will "break" again but probably I won't have a chance to do it until Monday.

simonrob commented 1 year ago

Thanks for following up. The new approach in this branch is clearly being used (see the duplicate error message at 2023-07-14 09:46:38, which I'll fix). But I'm puzzled about what else could be triggering this. Here are some thoughts/questions:

I appreciate that each one of these will take a while to investigate, given the period over which this is happening. But any further information you can provide about these theories will hopefully get closer to resolving this.

simonrob commented 1 year ago

Just to follow up: 9c42b6b separates token renewal from token decryption as mentioned above. I'd be interested to see what happens in your situation with this latest refinement.

Draykan commented 1 year ago

Thanks Simon, I really appreciate your efforts.

First, let me say that after updating macOS from version 13.4 to 13.4.1 (22F82) and restarting the proxy on Friday, yesterday (after three days since I re-authorised the IMAP account) the proxy still had not asked to re-authorise the account.🎉 The Mac was running the version in branch issue-183 (2023-07-12).

So yesterday I stopped the proxy, applied the Rapid Security Response 13.4.1 (c) that updated macOS to version 13.4.1 (22F770820d), updated the proxy to the version in branch issue-183 (2023-07-13) and started it in debug mode again. Hopefully, if it will error again, we will have more clues to investigate.

I'll answer your questions now:

  • Apart from the email address anonymisation, is this a complete, unedited log?

Yes it is, I didn't take out anything from the part of the log I posted.

  • I'm struggling to think of other reasons why the message at 2023-07-14 09:39:08 could take a full 5+ seconds to be passed to the server. Are you using the --cache-store option with AWS? If not, do you have an intermittent internet connection?

I'm not using the --cache-store option. Regarding the internet connection, the Mac affected by the issue is in use by another user of the company I work for, so I cannot be sure about the quality or specs of the Internet connection used by the Mac when it's out of the office. I can only say that the office internet connection used by the Mac usually is fast and reliable (and it's the same internet connection used by the Mac that's not affected by the issue).

  • Are you using multiple clients at once with the same account via the proxy? My assumption is that you are not, based on the consistent pattern in IMAP tags, but there is also some strange behaviour going on, in that the client sometimes identifies itself but sometimes does not, and also switches between LOGIN and PLAIN authentication methods. I don't know why it would do this.

No, the only e-mail client on that Mac that uses the proxy is Apple Mail. There is also Outlook for Mac installed on that Mac but it's not configured to use the proxy.

  • Do you have any idea why the client is repeatedly sending an authentication request but then closing the connection before it completes? (the first two attempts between the new connection messages) Was this something you were doing, or is this log just from background email activity?

I don't know… I wasn't in front of that Mac when those messages occurred but I think that the user did nothing and the log is just from background email activity. The user asks for my help each time it needs to reauthorise the IMAP account, so I don't believe he could have done anything strange.

If the issue has not already been fixed by the new proxy and macOS versions, I will try it the next time the proxy will ask to re-authorise the account.

  • I wonder if this is related to https://github.com/simonrob/email-oauth2-proxy/issues/155. The InvalidToken exception is primarily generated by the cryptography package that handles storage of the access tokens. The proxy overloads this exception, which it probably shouldn't do, since it can lead to unclear situations like this one. I'll look into refining this, but in the meantime, do you see any change in behaviour if you switch to a different version of the cryptography package? How about trying 38.0.1, or 41.0.2?

If the issue has not already been fixed by the new proxy and macOS versions, I will try it the next time the proxy will ask to re-authorise the account.

  • Are you changing the date/time at around the time this is happening?

No, I'm not changing any dates or times.

One unusual thing I noticed when I installed the version of the proxy in branch issue-183 (2023-07-12) and I had to re-authorise the IMAP account because the token had been previously invalidated, is that I had to re-authorise the IMAP account three times consecutively. After the first and second successfully authentication, the proxy was still asking to authorise the IMAP account but, oddly, it seems from the log that Apple Mail was actually fetching new e-mails even after the first and second authentications but eventually the token had been invalidated almost immediately.

This is the start of the log for that session (I removed the lines containing sensitive informations of the fetched e-mails):

2023-07-14 17:27:29,154: Received network reachable notification - status: 2
2023-07-14 17:27:29,224: Initialising Email OAuth 2.0 Proxy (version 2023-07-12) from config file /Applications/email-oauth2-proxy-issue-183/emailproxy.config
2023-07-14 17:27:29,224: Starting IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:27:29,237: Initialised Email OAuth 2.0 Proxy - listening for authentication requests. Connect your email client to begin
2023-07-14 17:27:38,825: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:27:38,826: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50695, 0, 0)
2023-07-14 17:27:38,845: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:27:38,861: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:27:38,903: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:27:38,915: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAyADAAMwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:27:38,916: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAyADAAMwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:27:38,918: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) --> b'1.9 CAPABILITY\r\n'
2023-07-14 17:27:38,918: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     --> b'1.9 CAPABILITY\r\n'
2023-07-14 17:27:38,933: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:27:38,935: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:27:38,935: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     <-- b'1.9 OK CAPABILITY completed.\r\n'
2023-07-14 17:27:38,935: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- b'1.9 OK CAPABILITY completed.\r\n'
2023-07-14 17:27:38,936: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) --> b'2.9 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:27:38,937: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     --> b'2.9 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:27:38,949: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:27:38,949: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:27:38,949: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     <-- b'2.9 OK ID completed\r\n'
2023-07-14 17:27:38,950: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- b'2.9 OK ID completed\r\n'
2023-07-14 17:27:38,951: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) --> b'4.9 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:27:39,058: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:27:50,751: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:27:51,832: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:02,009: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:02,856: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:05,762: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:06,294: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:21,638: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:22,354: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:34,794: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:35,577: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:28:38,969: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:28:38,970: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50698, 0, 0)
2023-07-14 17:28:38,991: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:28:39,002: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:28:39,042: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:28:39,054: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:28:39,054: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAwADUAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:28:39,056: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) --> b'1.10 CAPABILITY\r\n'
2023-07-14 17:28:39,056: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993)     --> b'1.10 CAPABILITY\r\n'
2023-07-14 17:28:39,069: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:28:39,069: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:28:39,070: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993)     <-- b'1.10 OK CAPABILITY completed.\r\n'
2023-07-14 17:28:39,070: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-- b'1.10 OK CAPABILITY completed.\r\n'
2023-07-14 17:28:39,071: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) --> b'2.10 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:28:39,146: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:29:36,233: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:29:36,234: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50727, 0, 0)
2023-07-14 17:29:36,253: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:29:36,261: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:29:36,299: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:29:36,311: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADAAMQAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:36,311: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADAAMQAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:36,312: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) --> b'1.11 CAPABILITY\r\n'
2023-07-14 17:29:36,313: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     --> b'1.11 CAPABILITY\r\n'
2023-07-14 17:29:36,326: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:36,326: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:36,326: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     <-- b'1.11 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:36,326: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-- b'1.11 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:36,327: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) --> b'2.11 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:29:36,327: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     --> b'2.11 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:29:36,340: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:29:36,340: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:29:36,341: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     <-- b'2.11 OK ID completed\r\n'
2023-07-14 17:29:36,341: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) <-- b'2.11 OK ID completed\r\n'
2023-07-14 17:29:36,342: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993) --> b'4.11 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:29:36,421: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:29:39,085: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:29:39,086: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50729, 0, 0)
2023-07-14 17:29:39,108: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:29:39,119: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:29:39,156: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:29:39,169: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADMAMAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:39,169: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADMAMAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:39,170: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) --> b'1.12 CAPABILITY\r\n'
2023-07-14 17:29:39,170: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993)     --> b'1.12 CAPABILITY\r\n'
2023-07-14 17:29:39,184: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:39,185: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:39,185: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993)     <-- b'1.12 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:39,186: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- b'1.12 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:39,186: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) --> b'2.12 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:29:39,260: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:29:42,465: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:42,465: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:42,465: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:42,465: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:43,388: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:43,388: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:43,388: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:43,388: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,168: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,169: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,170: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,170: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,549: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,550: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,550: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:56,550: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:58,190: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:58,190: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:58,190: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:58,191: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:29:58,512: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:29:58,512: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:29:58,512: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:29:58,513: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:29:58,766: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     --> b'4.11 AUTHENTICATE XOAUTH2 '
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993)     --> b'4.9 AUTHENTICATE XOAUTH2 '
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993)     --> b'2.10 AUTHENTICATE XOAUTH2 '
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993)     --> b'[[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) Caught connection error (server) - BrokenPipeError : [Errno 32] Broken pipe
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) Caught connection error (server) - BrokenPipeError : [Errno 32] Broken pipe
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:29:58,767: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:29:58,768: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) --> [ Client disconnected ]
2023-07-14 17:29:58,769: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) Caught client exception; server connection closed before data could be sent
2023-07-14 17:29:58,769: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) --> [ Client disconnected ]
2023-07-14 17:29:58,770: Warning: IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) unable to remove orphan client connection <__main__.IMAPOAuth2ClientConnection ('::1', 50695, 0, 0) at 0x1046265e0>
2023-07-14 17:29:58,770: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) Caught client exception; server connection closed before data could be sent
2023-07-14 17:29:58,770: IMAP (localhost:1993; ::1:50695->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:29:58,770: Warning: IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) unable to remove orphan client connection <__main__.IMAPOAuth2ClientConnection ('::1', 50698, 0, 0) at 0x10d6a4640>
2023-07-14 17:29:58,771: IMAP (localhost:1993; ::1:50698->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:29:58,791: Error requesting access token - received invalid response: {'error': 'invalid_grant', 'error_description': 'AADSTS54005: OAuth2 Authorization code was already redeemed, please retry with a new valid code or use an existing refresh token.\r\nTrace ID: f11f36d5-f1bc-414f-8678-f10076083b00\r\nCorrelation ID: 20e9c473-7fc8-4b13-b706-06b17976b165\r\nTimestamp: 2023-07-14 15:29:58Z', 'error_codes': [54005], 'timestamp': '2023-07-14 15:29:58Z', 'trace_id': 'f11f36d5-f1bc-414f-8678-f10076083b00', 'correlation_id': '20e9c473-7fc8-4b13-b706-06b17976b165'}
2023-07-14 17:29:58,792: Caught exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: {'error': 'invalid_grant', 'error_description': 'AADSTS54005: OAuth2 Authorization code was already redeemed, please retry with a new valid code or use an existing refresh token.\r\nTrace ID: f11f36d5-f1bc-414f-8678-f10076083b00\r\nCorrelation ID: 20e9c473-7fc8-4b13-b706-06b17976b165\r\nTimestamp: 2023-07-14 15:29:58Z', 'error_codes': [54005], 'timestamp': '2023-07-14 15:29:58Z', 'trace_id': 'f11f36d5-f1bc-414f-8678-f10076083b00', 'correlation_id': '20e9c473-7fc8-4b13-b706-06b17976b165'}
2023-07-14 17:29:58,792: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- b'2.12 NO LOGIN Email OAuth 2.0 Proxy: Login failed for account redacted_email@domain.ext - please check your internet connection and retry\r\n'
2023-07-14 17:29:58,792: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- b'* BYE Autologout; authentication failed\r\n'
2023-07-14 17:29:58,792: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) --> [ Client disconnected ]
2023-07-14 17:29:58,793: IMAP (localhost:1993; ::1:50729->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:29:59,397: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext)     <-- b'4.11 OK AUTHENTICATE completed.\r\n'
2023-07-14 17:29:59,397: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) [ Successfully authenticated IMAP connection - releasing session ]
2023-07-14 17:29:59,398: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'4.11 OK AUTHENTICATE completed.\r\n'
2023-07-14 17:29:59,399: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'5.11 CAPABILITY\r\n'
2023-07-14 17:29:59,427: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTACCESSRULES CLIENTNETWORKPRESENCELOCATION BACKENDAUTHENTICATE CHILDREN IDLE NAMESPACE LITERAL+\r\n5.11 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:59,432: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'6.11 SELECT INBOX\r\n'
2023-07-14 17:29:59,561: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3213 EXISTS\r\n* 0 RECENT\r\n* FLAGS (\\Seen \\Answered \\Flagged \\Deleted \\Draft $MDNSent)\r\n* OK [PERMANENTFLAGS (\\Seen \\Answered \\Flagged \\Deleted \\Draft $MDNSent)] Permanent flags\r\n* OK [UNSEEN 1914] Is the first unseen message\r\n* OK [UIDVALIDITY 14] UIDVALIDITY value\r\n* OK [UIDNEXT 14023] The next unique identifier value\r\n6.11 OK [READ-WRITE] SELECT completed.\r\n'
2023-07-14 17:29:59,570: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'7.11 UID FETCH 13995:14022 (INTERNALDATE UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from to cc message-id in-reply-to references content-type x-priority x-uniform-type-identifier x-universally-unique-identifier list-id list-unsubscribe bimi-indicator bimi-location x-bimi-indicator-hash authentication-results dkim-signature)])\r\n'

[removed_lines]

2023-07-14 17:29:59,851: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'7.11 OK FETCH completed.\r\n'
2023-07-14 17:29:59,856: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:29:59,856: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50740, 0, 0)
2023-07-14 17:29:59,863: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'8.11 FETCH 1888:3197 (FLAGS UID)\r\n'
2023-07-14 17:29:59,879: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:29:59,885: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:29:59,891: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 1888 FETCH (FLAGS (\\Seen) UID 9012)\r\n'

[removed_lines]

2023-07-14 17:29:59,910: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3197 FETCH (FLAGS (\\Seen) UID 13994)\r\n8.11 OK FETCH completed.\r\n'
2023-07-14 17:29:59,921: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:29:59,924: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'9.11 UID FETCH 14019 (BODYSTRUCTURE BODY.PEEK[HEADER])\r\n10.11 UID FETCH 14013 BODYSTRUCTURE\r\n'
2023-07-14 17:29:59,924: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'11.11 UID FETCH 14017:14018,14020:14022 (BODY.PEEK[] BODYSTRUCTURE)\r\n'
2023-07-14 17:29:59,941: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSAEEAUAAyADcAOABDAEEAMAAwADAAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:59,941: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSAEEAUAAyADcAOABDAEEAMAAwADAAMgAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:29:59,941: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) --> b'1.13 CAPABILITY\r\n'
2023-07-14 17:29:59,941: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     --> b'1.13 CAPABILITY\r\n'
2023-07-14 17:29:59,957: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:59,958: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:29:59,958: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     <-- b'1.13 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:59,958: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-- b'1.13 OK CAPABILITY completed.\r\n'
2023-07-14 17:29:59,958: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) --> b'2.13 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:29:59,958: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     --> b'2.13 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:29:59,976: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:29:59,976: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:29:59,976: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     <-- b'2.13 OK ID completed\r\n'
2023-07-14 17:29:59,977: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) <-- b'2.13 OK ID completed\r\n'
2023-07-14 17:29:59,977: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993) --> b'4.13 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:30:00,038: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 17:30:00,087: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 17:30:00,133: Authorisation request received for redacted_email@domain.ext (interactive mode)

[removed_lines]

2023-07-14 17:30:05,741: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'72.11 IDLE\r\n'
2023-07-14 17:30:05,768: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'+ IDLE accepted, awaiting DONE command.\r\n'
2023-07-14 17:30:18,458: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'DONE\r\n'
2023-07-14 17:30:18,496: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'72.11 OK IDLE completed.\r\n'
2023-07-14 17:30:18,496: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'73.11 UNSELECT\r\n'
2023-07-14 17:30:18,530: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'73.11 OK UNSELECT completed.\r\n'
2023-07-14 17:30:18,531: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'74.11 SELECT INBOX\r\n'
2023-07-14 17:30:18,625: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 3213 EXISTS\r\n* 0 RECENT\r\n* FLAGS (\\Seen \\Answered \\Flagged \\Deleted \\Draft $MDNSent)\r\n* OK [PERMANENTFLAGS (\\Seen \\Answered \\Flagged \\Deleted \\Draft $MDNSent)] Permanent flags\r\n* OK [UNSEEN 1914] Is the first unseen message\r\n* OK [UIDVALIDITY 14] UIDVALIDITY value\r\n* OK [UIDNEXT 14023] The next unique identifier value\r\n74.11 OK [READ-WRITE] SELECT completed.\r\n'
2023-07-14 17:30:18,627: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'75.11 FETCH 1:3213 (FLAGS UID)\r\n'
2023-07-14 17:30:18,657: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* 1 FETCH (FLAGS (\\Seen) UID 3)\r\n'

[removed_lines]

2023-07-14 17:30:18,992: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) --> b'101.11 IDLE\r\n'
2023-07-14 17:30:19,043: IMAP (localhost:1993; ::1:50727->outlook.office365.com:993; redacted_email@domain.ext) <-- b'+ IDLE accepted, awaiting DONE command.\r\n'
2023-07-14 17:30:20,613: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:30:20,614: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50742, 0, 0)
2023-07-14 17:30:20,640: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:30:20,647: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:30:20,686: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:30:20,700: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAOAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:30:20,700: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAOAAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:30:20,701: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) --> b'1.14 CAPABILITY\r\n'
2023-07-14 17:30:20,701: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     --> b'1.14 CAPABILITY\r\n'
2023-07-14 17:30:20,714: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:30:20,715: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:30:20,715: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     <-- b'1.14 OK CAPABILITY completed.\r\n'
2023-07-14 17:30:20,715: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'1.14 OK CAPABILITY completed.\r\n'
2023-07-14 17:30:20,716: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) --> b'2.14 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:30:20,716: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     --> b'2.14 ID ("name" "Mac OS X Mail" "version" "16.0 (3731.600.7)" "os" "Mac OS X" "os-version" "13.4.1 (22F82)" "vendor" "Apple Inc.")\r\n'
2023-07-14 17:30:20,729: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:30:20,730: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'* ID ("name" "Microsoft.Exchange.Imap4.Imap4Server" "version" "15.20")\r\n'
2023-07-14 17:30:20,730: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993)     <-- b'2.14 OK ID completed\r\n'
2023-07-14 17:30:20,730: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'2.14 OK ID completed\r\n'
2023-07-14 17:30:20,731: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) --> b'4.14 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:30:20,806: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:30:26,510: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:26,511: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:27,164: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:27,165: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:39,106: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:39,106: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:39,720: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:39,720: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:41,470: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:41,470: Waiting for URL matching `redirect_uri`; following browser redirection to login.microsoftonline.com/[...]
2023-07-14 17:30:41,801: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:30:41,801: Returning authorisation request result for redacted_email@domain.ext
2023-07-14 17:30:42,031: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     --> b'4.13 AUTHENTICATE XOAUTH2 '
2023-07-14 17:30:42,032: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993)     --> b'[[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:30:42,101: Error requesting access token - received invalid response: {'error': 'invalid_grant', 'error_description': 'AADSTS54005: OAuth2 Authorization code was already redeemed, please retry with a new valid code or use an existing refresh token.\r\nTrace ID: e43d1845-97ed-4ce6-b557-3447f7193000\r\nCorrelation ID: e5563f9f-4430-43f3-90b5-eb9394e6ac2e\r\nTimestamp: 2023-07-14 15:30:42Z', 'error_codes': [54005], 'timestamp': '2023-07-14 15:30:42Z', 'trace_id': 'e43d1845-97ed-4ce6-b557-3447f7193000', 'correlation_id': 'e5563f9f-4430-43f3-90b5-eb9394e6ac2e'}
2023-07-14 17:30:42,101: Caught exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: {'error': 'invalid_grant', 'error_description': 'AADSTS54005: OAuth2 Authorization code was already redeemed, please retry with a new valid code or use an existing refresh token.\r\nTrace ID: e43d1845-97ed-4ce6-b557-3447f7193000\r\nCorrelation ID: e5563f9f-4430-43f3-90b5-eb9394e6ac2e\r\nTimestamp: 2023-07-14 15:30:42Z', 'error_codes': [54005], 'timestamp': '2023-07-14 15:30:42Z', 'trace_id': 'e43d1845-97ed-4ce6-b557-3447f7193000', 'correlation_id': 'e5563f9f-4430-43f3-90b5-eb9394e6ac2e'}
2023-07-14 17:30:42,102: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'4.14 NO AUTHENTICATE Email OAuth 2.0 Proxy: Login failed for account redacted_email@domain.ext - please check your internet connection and retry\r\n'
2023-07-14 17:30:42,102: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- b'* BYE Autologout; authentication failed\r\n'
2023-07-14 17:30:42,102: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) --> [ Client disconnected ]
2023-07-14 17:30:42,104: IMAP (localhost:1993; ::1:50742->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-14 17:30:42,108: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-14 17:30:42,108: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 50750, 0, 0)
2023-07-14 17:30:42,129: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) --> [ Client connected ]
2023-07-14 17:30:42,139: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-14 17:30:42,175: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-14 17:30:42,178: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAMwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:30:42,178: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADEAMwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-14 17:30:42,179: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) --> b'1.17 CAPABILITY\r\n'
2023-07-14 17:30:42,179: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993)     --> b'1.17 CAPABILITY\r\n'
2023-07-14 17:30:42,192: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:30:42,192: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-14 17:30:42,192: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993)     <-- b'1.17 OK CAPABILITY completed.\r\n'
2023-07-14 17:30:42,192: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) <-- b'1.17 OK CAPABILITY completed.\r\n'
2023-07-14 17:30:42,193: IMAP (localhost:1993; ::1:50750->outlook.office365.com:993) --> b'2.17 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-14 17:30:42,264: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 17:30:42,310: Retrying login due to exception while requesting OAuth 2.0 credentials for redacted_email@domain.ext: InvalidToken()
2023-07-14 17:30:42,355: Authorisation request received for redacted_email@domain.ext (interactive mode)
2023-07-14 17:30:42,752: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993; redacted_email@domain.ext)     <-- b'4.13 OK AUTHENTICATE completed.\r\n'
2023-07-14 17:30:42,752: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993; redacted_email@domain.ext) [ Successfully authenticated IMAP connection - releasing session ]
2023-07-14 17:30:42,753: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993; redacted_email@domain.ext) <-- b'4.13 OK AUTHENTICATE completed.\r\n'
2023-07-14 17:30:42,754: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993; redacted_email@domain.ext) --> b'5.13 CAPABILITY\r\n'
2023-07-14 17:30:42,782: IMAP (localhost:1993; ::1:50740->outlook.office365.com:993; redacted_email@domain.ext) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS MOVE ID UNSELECT CLIENTACCESSRULES CLIENTNETWORKPRESENCELOCATION BACKENDAUTHENTICATE CHILDREN IDLE NAMESPACE LITERAL+\r\n5.13 OK CAPABILITY completed.\r\n'

I don't know if you can see a pattern in the log above, the only different thing I remember doing different than the other times is that initially I tried to use a wrong e-mail address to authorise the shared e-mail account in the embedded browser window, then I noticed and corrected it but I had to authorise the account three times in a row.

simonrob commented 1 year ago

Thanks for following up with this detailed response. I hope the new version has indeed resolved things here.

Please could you check you are actually using the latest commit from this branch, though? In the most recent log you've posted, at 17:30:00,038 the same error message is given twice, with the older wording, and missing the update in 9c42b6b that differentiates between similar errors here. It's worth doing so to be sure sure that this is resolved, because the most recent version tries to properly separate out InvalidToken from other errors, which could well reveal other issues.

Re: multiple authentication requests, I think this is probably caused by your email client opening multiple connections before a single one has actually succeeded (again, slightly strangely, with five via AUTHENTICATE PLAIN and two via LOGIN). At 17:29:58,512 in the log you authorise one of these, and the proxy returns the resulting code to all existing requests, but two connections have since timed out, and using the same code for the remaining two at the same time leads to an invalid_grant error at 17:29:58,791 because these tokens can only be used once.

The proxy doesn't remove failed tokens here because of the potential for exactly this situation. However, by the next time a connection is tried, the token should have been saved by the proxy via the successful connection. So, I suspect the repeated requests may be related to #155, which is to do with the proxy's lack of explicit handling of concurrent writes to the configuration file. I do intend to address this, but haven't had time recently.

In the meantime, please do let me know if this issue crops up again, particularly if you can update to 9c42b6b.

simonrob commented 1 year ago

I'm planning to merge this branch if all is well. I presume that is the case since there have been no further updates, but please do let me know if you're still encountering problems.

Draykan commented 1 year ago

Hi Simon, I'm sorry for the long absence.

Please could you check you are actually using the latest commit from this branch, though? In the most recent log you've posted, at 17:30:00,038 the same error message is given twice, with the older wording, and missing the update in https://github.com/simonrob/email-oauth2-proxy/commit/9c42b6b4ab98e78aac9b3383cfedba00bfe3d4d4 that differentiates between similar errors here.

It's correct, that log has the double error message because it comes from branch issue-183 (2023-07-12) when I restarted the proxy after that release 2023-05-18 had an authentication failure and I had to re-authorise the IMAP account. At the time I wasn't yet aware of version branch issue-183 (2023-07-13) so I installed branch issue-183 (2023-07-12).

So, I suspect the repeated requests may be related to https://github.com/simonrob/email-oauth2-proxy/issues/155, which is to do with the proxy's lack of explicit handling of concurrent writes to the configuration file. I do intend to address this, but haven't had time recently.

👍

I'm planning to merge this branch if all is well. I presume that is the case since there have been no further updates, but please do let me know if you're still encountering problems.

Unfortunately I have to report a failure with version branch issue-183 (2023-07-13) and macOS 13.4.1 (22F770820d). This is the piece of log with the InvalidToken() error:

2023-07-18 23:16:43,022: IMAP (localhost:1993; ::1:59807->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-18 23:16:43,027: IMAP (localhost:1993; ::1:59807->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-18 23:16:43,027: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-18 23:16:43,027: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 59825, 0, 0)
2023-07-18 23:16:43,141: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) --> [ Client connected ]
2023-07-18 23:16:43,151: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-18 23:16:43,193: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-18 23:16:43,204: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADQAMQAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-18 23:16:43,205: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADAAUAAyADcAOABDAEEAMAAxADQAMQAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-18 23:16:43,206: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) --> b'1.208 CAPABILITY\r\n'
2023-07-18 23:16:43,206: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     --> b'1.208 CAPABILITY\r\n'
2023-07-18 23:16:43,218: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-18 23:16:43,218: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-18 23:16:43,218: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     <-- b'1.208 OK CAPABILITY completed.\r\n'
2023-07-18 23:16:43,219: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-- b'1.208 OK CAPABILITY completed.\r\n'
2023-07-18 23:16:43,220: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) --> b'2.208 AUTHENTICATE PLAIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-18 23:16:43,313: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     --> b'2.208 AUTHENTICATE XOAUTH2 '
2023-07-18 23:16:43,313: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993)     --> b'[[ Credentials removed from proxy log ]]\r\n'
2023-07-18 23:32:47,843: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993; redacted_email@domain.ext) --> [ Client disconnected ]
2023-07-18 23:32:47,846: IMAP (localhost:1993; ::1:59825->outlook.office365.com:993) <-- [ Server disconnected ]
2023-07-18 23:32:47,847: New incoming connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS)
2023-07-18 23:32:47,847: Accepting new connection to IMAP server at localhost:1993 (unsecured) proxying outlook.office365.com:993 (SSL/TLS) via ('::1', 59831, 0, 0)
2023-07-18 23:32:47,871: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) --> [ Client connected ]
2023-07-18 23:32:47,888: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) <-> [ Starting TLS handshake ]
2023-07-18 23:32:47,927: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) <-> [ TLSv1.2 handshake complete ]
2023-07-18 23:32:47,938: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993)     <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADYANwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-18 23:32:47,938: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) <-- b'* OK The Microsoft Exchange IMAP4 service is ready. [WgBSADIAUAAyADcAOABDAEEAMAAwADYANwAuAEMASABFAFAAMgA3ADgALgBQAFIATwBEAC4ATwBVAFQATABPAE8ASwAuAEMATwBNAA==]\r\n'
2023-07-18 23:32:47,939: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) --> b'1.209 CAPABILITY\r\n'
2023-07-18 23:32:47,939: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993)     --> b'1.209 CAPABILITY\r\n'
2023-07-18 23:32:47,951: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993)     <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN AUTH=XOAUTH2 SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-18 23:32:47,951: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) <-- b'* CAPABILITY IMAP4 IMAP4rev1 AUTH=PLAIN SASL-IR UIDPLUS ID UNSELECT CHILDREN IDLE NAMESPACE LITERAL+\r\n'
2023-07-18 23:32:47,952: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993)     <-- b'1.209 OK CAPABILITY completed.\r\n'
2023-07-18 23:32:47,952: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) <-- b'1.209 OK CAPABILITY completed.\r\n'
2023-07-18 23:32:47,953: IMAP (localhost:1993; ::1:59831->outlook.office365.com:993) --> b'2.209 LOGIN [[ Credentials removed from proxy log ]]\r\n'
2023-07-18 23:32:48,040: Retrying login due to exception while decrypting OAuth 2.0 credentials for redacted_email@domain.ext (invalid password): InvalidToken()
2023-07-18 23:32:48,087: Authorisation request received for redacted_email@domain.ext (interactive mode)

That invalid password makes me wondering if the user received a notification or a message from Mail like this and tried to enter a different password from the one used in the Mail settings, causing the proxy to delete the account token since delete_account_token_on_password_error is True:

Mail password request

I'm sorry that the text in the notification is in Italian, in English it should be more or less like this: _Mail Password Request Enter the password for "redactedemail@domain.ext" in Internet Accounts.

I'd like to ask the user if that's the case but unfortunately he is on vacation at the moment and he won't be back to work before 3 weeks, so I suppose we have to suspend troubleshooting this issue until then. 🫤 In the meantime, do you have anything in mind that could cause that decrypting error without user intervention? Thank you.

simonrob commented 1 year ago

No worries – thanks for following up.

I think you may be on to something by asking the user about password usage. I can't think of any other reason for this, particularly with the issue-183 branch, which will now only give the InvalidToken error when there is an issue with the stored credentials.

I'd start by disabling delete_account_token_on_password_error and seeing what happens. I'll keep this issue open until you can try this – no hurry.

simonrob commented 1 year ago

Have you had chance to try this out?

Draykan commented 1 year ago

I'm sorry but I'll probably need another week as the user should be back to work now but I am the one on vacation this week… 😞

simonrob commented 1 year ago

Let me know when you get chance to do this?

The issue-183 branch is now up to date with recent changes from the main branch too.

Draykan commented 1 year ago

Hi Simon, I had a chance to catch up with the user and he says that he might have tried to enter a password at the unneeded Mail notification requesting to insert a password for the proxied IMAP account. So, to eliminate any user error, I set delete_account_token_on_password_error to False and it's been about a week now that the proxy is running without any issue. I think you can safely merge this branch now. Thank you very much for your work, I've really appreciated your efforts to solve this issue.

simonrob commented 1 year ago

Thanks for checking this – I'll go ahead and merge this branch. Thanks also for your help in identifying and testing this change – really appreciated!