Bug 485799

Summary: Get a lot of `Failed to process EWS request: ` with empty details
Product: [Frameworks and Libraries] Akonadi Reporter: arcticlampyrid
Component: EWS ResourceAssignee: kdepim bugs <kdepim-bugs>
Status: CONFIRMED ---    
Severity: normal CC: carl, krissn, lbeltrame, michel.munnix
Priority: NOR    
Version: unspecified   
Target Milestone: ---   
Platform: Arch Linux   
OS: Linux   
Latest Commit: Version Fixed In:
Attachments: log from akonadiconsole

Description arcticlampyrid 2024-04-19 16:26:01 UTC
Get a lot of `Failed to process EWS request: ` with empty details

```log
QT_LOGGING_RULE=log_ews_resource_request.debug=true /usr/bin/akonadi_ews_resource --identifier akonadi_ews_resource_3
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
org.kde.pim.ews.client: Failed to process EWS request: 
```
Comment 1 michel munnix 2024-04-29 18:15:19 UTC
Created attachment 169010 [details]
log from akonadiconsole

I have the same messages repeated in journalctl.
There is also a memory leak that makes the akonadi_ews_res process grow:
top with interval: 10 sec
continuous increase of akonadi_ews_res RES size:

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                     
                            
 4317 mm        20   0 2545384 580612  11784 S 5.389 15.28   0:41.93 akonadi_ews_res                             
 4317 mm        20   0 2553160 587140  11656 S 5.389 15.45   0:42.47 akonadi_ews_res                             
 4317 mm        20   0 2562660 594564  11656 S 5.694 15.65   0:43.04 akonadi_ews_res                             

opensuse tumbleweed
kdepim-runtime-24.02.2-1.1.x86_64
Comment 2 Luca Beltrame 2024-05-09 06:18:24 UTC
This is because malformed data is sent, this is the reply from the server (you should set QT_LOGGING_RULES="*org.kde.pim.ews.client.proto*.debug=true" to have it dumped somewhere):

<?xml version="1.0" encoding="utf-8"?><s:Envelope xmlns:s="http://schemas.xmlsoap.org/soap/envelope/"><s:Body><s:Fault><faultcode xmlns:a="http://schemas.microsoft.com/exchange/services/2006/types">a:ErrorInvalidOperation</faultcode><faultstring xml:lang="en-US">Id is malformed.</faultstring><detail><e:ResponseCode xmlns:e="http://schemas.microsoft.com/exchange/services/2006/errors">ErrorInvalidOperation</e:ResponseCode><e:Message xmlns:e="http://schemas.microsoft.com/exchange/services/2006/errors">Id is malformed.</e:Message></detail></s:Fault></s:Body></s:Envelope>

I haven't found a way to debug *why* it's invalid.
Comment 3 Luca Beltrame 2024-05-09 07:17:51 UTC
(In reply to Luca Beltrame from comment #2)
 
> I haven't found a way to debug *why* it's invalid.

dd785b95af83fd74618b5e4ce2904fa86db771e3 in kdepim-runtime might be suspect, but I have no way of confirming it.
Comment 4 Luca Beltrame 2024-06-26 09:14:29 UTC
The memory leak at least should be fixed (doesn't leak anymore in my tests) by https://invent.kde.org/pim/kdepim-runtime/-/commit/aacd0807f13d0694b2bde515964b5f081973da5f. The spam in the log is a different issue.
Comment 5 Carl Schwan 2024-06-26 09:21:04 UTC
Do you maybe have a the body of one of the EWS request with an invalid ID?

Locally I get:

org.kde.pim.ews.client.proto: "<?xml version=\"1.0\"?><soap:Envelope xmlns:soap=\"http://schemas.xmlsoap.org/soap/envelope/\" xmlns:m=\"http://schemas.microsoft.com/exchange/services/2006/messages\" xmlns:t=\"http://schemas.microsoft.com/exchange/services/2006/types\"><soap:Header><t:RequestServerVersion Version=\"Exchange2007_SP1\"/></soap:Header><soap:Body><m:GetItem><m:ItemShape><t:BaseShape>IdOnly</t:BaseShape><t:AdditionalProperties><t:FieldURI FieldURI=\"item:MimeContent\"/></t:AdditionalProperties></m:ItemShape><m:ItemIds><t:ItemId Id=\"AAMkADgzNzkyOTg1LWZmYzgtNDY3Zi1hMjU2LTFlODNlZGIxNTVlNgBGAAAAAACGij6e2qxSSoxGqEgp0YQIBwAQB6nxUL4fQLR2Ugu0H+JMAAAAAAEMAAAQB6nxUL4fQLR2Ugu0H+JMAATIyE6cAAA=\" ChangeKey=\"CQAAABYAAAAQB6nxUL4fQLR2Ugu0H+JMAATLClcH\"/></m:ItemIds></m:GetItem></soap:Body></soap:Envelope>\n"

and this is valid according to Outlook/Office365.
Comment 6 Bug Janitor Service 2024-06-26 18:38:36 UTC
A possibly relevant merge request was started @ https://invent.kde.org/pim/kdepim-runtime/-/merge_requests/170
Comment 7 Louis Moureaux 2024-06-26 22:45:13 UTC
Git commit 46ad0976a178a0189fe9fea6ec99f4a8a15b5af3 by Louis Moureaux.
Committed on 26/06/2024 at 18:37.
Pushed by carlschwan into branch 'master'.

Do not try to subscribe to an empty list of folders

The server refuses to watch when the list of folders is empty, which
caused EwsSubscribedFoldersJob to try and subscribe in a loop. Just
subscribe to the default folder list when this happens so we avoid the
error. Subscribing still fails with a timeout, but at least we're not
trying to do something invalid.

M  +2    -2    resources/ews/ewssubscribedfoldersjob.cpp

https://invent.kde.org/pim/kdepim-runtime/-/commit/46ad0976a178a0189fe9fea6ec99f4a8a15b5af3
Comment 8 Carl Schwan 2024-06-26 22:45:50 UTC
Git commit 05864950c3d0956bb9cb3148acc1245825cdde77 by Carl Schwan.
Committed on 26/06/2024 at 22:45.
Pushed by carlschwan into branch 'release/24.05'.

Do not try to subscribe to an empty list of folders

The server refuses to watch when the list of folders is empty, which
caused EwsSubscribedFoldersJob to try and subscribe in a loop. Just
subscribe to the default folder list when this happens so we avoid the
error. Subscribing still fails with a timeout, but at least we're not
trying to do something invalid.


(cherry picked from commit 46ad0976a178a0189fe9fea6ec99f4a8a15b5af3)

Co-authored-by: Louis Moureaux <m_louis30@yahoo.com>

M  +2    -2    resources/ews/ewssubscribedfoldersjob.cpp

https://invent.kde.org/pim/kdepim-runtime/-/commit/05864950c3d0956bb9cb3148acc1245825cdde77