EWS calendar not loading with 3.46.1 (Socket I/O timeout)
OS: ArchLinux
Evolution versions: evolution 3.46.1 / evolution-data-server 3.46.1 / evolution-ews 3.46.1
Email server: Microsoft Exchange Server 2013 (on-premise)
Since the upgrade to 3.46.1 my EWS calendar is no longer loading from the server. Downgrading to 3.44.4 makes the issue disappear.
After some initial discussion in issue #199 (closed) I cleared my ~/.cache/evolution and ran evolution-calendar-factory -w
with EWS_DEBUG=1
.
There is a long stream of HTTP requests and replies, which at one point seems to stall. After a couple of seconds I get an error message in the GUI (Evolution) stating there was a time-out during socket I/O. Once this error is shown the stream of requests continues.
The last couple of transactions before the stall look like this (redacted for privacy):
> CONNECT owa.mydomain.com:443 HTTP/1.1
> Soup-Debug-Timestamp: 1667987380
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 25 (0x7f90680b1810), GSocket 13 (0x56004b6e2d00)
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Connection: Keep-Alive
> Host: owa.mydomain.com
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCO
QVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
< HTTP/1.1 200 Connection established
< Soup-Debug-Timestamp: 1667987380
< Soup-Debug: SoupMessage 25 (0x7f90680b1810)
< Proxy-Connection: keep-alive
> POST /EWS/Exchange.asmx HTTP/1.1
> Soup-Debug-Timestamp: 1667987380
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 26 (0x56004b6c8b90), GSocket 13 (0x56004b6e2d00)
> Cache-Control: no-cache
> Pragma: no-cache
> Content-Type: text/xml; charset=utf-8
> Content-Length: 39931
> User-Agent: Evolution/3.46.1
> Connection: Keep-Alive
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Host: owa.mydomain.com
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCO
QVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
> Authorization: NTLM TlRMT...[private]
< HTTP/1.1 401 Unauthorized
< Soup-Debug-Timestamp: 1667987380
< Soup-Debug: SoupMessage 26 (0x56004b6c8b90)
< Server: Microsoft-IIS/8.5
< WWW-Authenticate: NTLM TlRMT...[private]
< WWW-Authenticate: Basic realm="owa.mydomain.com"
< WWW-Authenticate: Negotiate
< Date: Wed, 09 Nov 2022 09:49:40 GMT
< Content-Length: 0
< request-id: 0fdfe935-a51c-425f-8761-97fcd820f490
< X-OWA-Version: 15.0.1497.42
< X-Powered-By: ASP.NET
< X-FEServer: SRVOWA01
> POST /EWS/Exchange.asmx HTTP/1.1
> Soup-Debug-Timestamp: 1667987380
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 26 (0x56004b6c8b90), GSocket 13 (0x56004b6e2d00), restarted
> Cache-Control: no-cache
> Pragma: no-cache
> Content-Type: text/xml; charset=utf-8
> User-Agent: Evolution/3.46.1
> Connection: Keep-Alive
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Host: owa.mydomain.com
> Content-Length: 39931
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCO
QVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
> Authorization: NTLM TlRMT...[private]
After the I/O time-out this is how the stream continues:
> CONNECT owa.mydomain.com:443 HTTP/1.1
> Soup-Debug-Timestamp: 1667987405
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 27 (0x7f90680b12c0), GSocket 14 (0x56004b6e2bb0)
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Connection: Keep-Alive
> Host: owa.mydomain.com
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCOQVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
< HTTP/1.1 200 Connection established
< Soup-Debug-Timestamp: 1667987405
< Soup-Debug: SoupMessage 27 (0x7f90680b12c0)
< Proxy-Connection: keep-alive
> POST /EWS/Exchange.asmx HTTP/1.1
> Soup-Debug-Timestamp: 1667987405
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 28 (0x56004b6c8a80), GSocket 14 (0x56004b6e2bb0)
> Cache-Control: no-cache
> Pragma: no-cache
> Content-Type: text/xml; charset=utf-8
> Content-Length: 1398
> User-Agent: Evolution/3.46.1
> Connection: Keep-Alive
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Host: owa.mydomain.com
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCOQVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
> Authorization: NTLM TlRMT...[private]
< HTTP/1.1 401 Unauthorized
< Soup-Debug-Timestamp: 1667987405
< Soup-Debug: SoupMessage 28 (0x56004b6c8a80)
< Server: Microsoft-IIS/8.5
< WWW-Authenticate: NTLM TlRMT...[private]
< WWW-Authenticate: Basic realm="owa.mydomain.com"
< WWW-Authenticate: Negotiate
< Date: Wed, 09 Nov 2022 09:50:04 GMT
< Content-Length: 0
< request-id: 9a9f17fc-cd8e-4f5e-86e4-37d222a5d349
< X-OWA-Version: 15.0.1497.42
< X-Powered-By: ASP.NET
< X-FEServer: SRVOWA01
> POST /EWS/Exchange.asmx HTTP/1.1
> Soup-Debug-Timestamp: 1667987405
> Soup-Debug: ESoupSession 1 (0x7f906805f100), SoupMessage 28 (0x56004b6c8a80), GSocket 14 (0x56004b6e2bb0), restarted
> Cache-Control: no-cache
> Pragma: no-cache
> Content-Type: text/xml; charset=utf-8
> User-Agent: Evolution/3.46.1
> Connection: Keep-Alive
> Accept-Encoding: gzip, deflate, br
> Accept-Language: de-de, de;q=0.9
> Host: owa.mydomain.com
> Content-Length: 1398
> Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcvGxcvP; ClientId=FLCOQVYUIXDXOTCMJTQ; exchangecookie=3320[private]45b
> Authorization: NTLM TlRMT...[private]
< HTTP/1.1 200 OK
< Soup-Debug-Timestamp: 1667987405
< Soup-Debug: SoupMessage 28 (0x56004b6c8a80)
< Cache-Control: private
< Transfer-Encoding: chunked
< Content-Type: text/xml; charset=utf-8
< Content-Encoding: gzip
< Vary: Accept-Encoding
< Server: Microsoft-IIS/8.5
< Set-Cookie: exchangecookie=3320[private]45b; path=/
< Set-Cookie: X-BackEndCookie=S-1-5-21-878839295-1385979706-142223018-9135=u56Ln[private]s7N0s/Gq8/GxcrPxc/K; expires=Fri, 09-Dec-2022 09:50:05 GMT; path=/EWS; secure; HttpOnly
< Date: Wed, 09 Nov 2022 09:50:04 GMT
< request-id: 8fd6df8c-062f-4695-8d61-8be407d98c20
< X-CalculatedBETarget: srvmail02.mydomain.lan
< X-DiagInfo: SRVMAIL02
< X-BEServer: SRVMAIL02
< X-AspNet-Version: 4.0.30319
< Persistent-Auth: true
< X-Powered-By: ASP.NET
< X-FEServer: SRVOWA01
I see a lot of HTTP/1.1 401 Unauthorized
yet the EWS address books and mail works just fine, so I'm not sure how this could be an authorization issue.
The only error messages in the debug log I can spot are these:
[EWS] 2022-11-09 10:50:30.980 - e_ews_notification_get_events_sync: 0x7f90680b0ae0: finished reading events; cancelled:0 err:Socket I/O timed out is-partial-input:0
[EWS] 2022-11-09 10:50:30.981 - e_ews_notification_get_events_thread: Failed to get notification events (SubscriptionId: 'FQBzcn[private]AKA=')
I can provide the entire debug log or run with EWS_DEBUG=2
if that helps. In case of the latter I would just need time to do careful 'cleaning' off sensitive information.