Scalable OGo (SOGo)

View Issue Details Jump to Notes ] Related Changesets ] Issue History ] Print ]
IDProjectCategoryView StatusDate SubmittedLast Update
0004275SOGoActiveSyncpublic2017-09-06 10:462017-10-11 11:20
Reporterbgaussen 
Assigned Toludovic 
PriorityhighSeveritymajorReproducibilityalways
StatusresolvedResolutionfixed 
PlatformAppleOSiOSOS Version10
Product Version3.2.10 
Target VersionFixed in Version3.2.11 
Summary0004275: EAS Sync requests for Shared folder every second
DescriptionDigging into battery drain issue on my iPhone and iPad, I saw in sogo logs a lot of requests (several per second) for a quite long period of time (around 10 minutes):

    "POST /SOGo/Microsoft-Server-ActiveSync?User=ben@trez.org&DeviceId=QA3BBMUC3D51T1R5TMGCFO5DJO&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 0/65 0.426 - - 0

After enabling SOGoEASDebugEnabled, the request body is :

    sogod [27]: <0x0x56013dad9630[SOGoActiveSyncDispatcher]> EAS - request for device QA3BBMUC3D51T1R5TMGCFO5DJO: <?xml version="1.0"?>
    <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> [^]
    <Sync xmlns="AirSync:">
    <Collections>
    <Collection>
    <SyncKey>0</SyncKey>
    <CollectionId>mail%2FShared</CollectionId>
    <Options>
    <FilterType>5</FilterType>
    <MIMETruncation>1</MIMETruncation>
    <MIMESupport>0</MIMESupport>
    <BodyPreference xmlns="AirSyncBase:">
    <Type>1</Type>
    <TruncationSize>500</TruncationSize>
    </BodyPreference>
    </Options>
    </Collection>
    </Collections>
    </Sync>
    sogod [27]: <0x0x56013e18ee90[NGImap4Client]> TLS started successfully.
    sogod [27]: 83.197.145.212 "POST /SOGo/Microsoft-Server-ActiveSync?User=ben@trez.org&DeviceId=QA3BBMUC3D51T1R5TMGCFO5DJO&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 0/65 0.453 - - 480K

A network trace indicates an empty response from the server :

    HTTP/1.1 200 OK
    MS-Server-ActiveSync: 14.1
    MS-ASProtocolVersions: 2.5,12.0,12.1,14.0,14.1
    MS-ASProtocolCommands: Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,Search,Settings,Ping,ItemOperations,ResolveRecipi ents,ValidateCert
    Content-Type: application/vnd.ms-sync.wbxml
    Content-Length: 0


As far I understand ActiveSync protocol, an intial Sync command (with a SyncKey value of 0) requires a response with a SyncKey with a non null value. But here sogo answers with an empty response, so iOS client tries again and again for a long period, draining the battery...

The issue seems to be linked with the "special" Shared mailbox. In my setup there is no other user mailbox sharing with my account.
If I enable "Synchronize only default mail folders (EAS)" in sogo webmail parameters for my account, the Shared mailbox is not listed in initial FolderSync response and there is no issue.

As a side note, in sogo webmail, when I click on "Other Users" folder (not the icon but the text), I get the following error in sogo log :

    sogod [75]: [ERROR] <0x0x56013e7e63f0[NGImap4Connection]> could not select URL: imaps://ben%40trez.org@dovecot/Shared/?tls=YES: {RawResponse = "{ResponseResult = {description = \"Mailbox doesn't exist: Shared (0.001 + 0.041 + 0.040 secs).\"; result = no; tagId = 7; }; }"; reason = "Mailbox doesn't exist: Shared (0.001 + 0.041 + 0.040 secs)."; result = 0; }
Steps To Reproduce- Make sure "Synchronize only default mail folders (EAS)" is disabled for the account
- There is no mailbox sharing for the account
- Configure ActiveSync account on iOS device
- iOS mail client will start to make the Sync requests
Additional Informationsogo+dovecot part of mailcow
TagsNo tags attached.
Attached Files

- Relationships Relation Graph ] Dependency Graph ]

-  Notes
(0012266)
tfu (reporter)
2017-09-06 11:51

What shows following command on your server?
doveadm mailbox list -u user
(0012267)
bgaussen (reporter)
2017-09-06 11:53

# doveadm mailbox list -u xxx@xxx.xxx
Sent
Trash
Archive
Junk
Drafts
Shared
INBOX
(0012268)
tfu (reporter)
2017-09-06 12:20

Try to set

list = children

for namespace type=shared.
(0012269)
bgaussen (reporter)
2017-09-06 15:43

Hi,

I changed dovecot configuration with list=children in namespace type=shared.

doveadm does not list anymore Shared mailbox :

# doveadm mailbox list -u xxx@xxxx.xxx
Sent
Trash
Archive
Junk
Personnel
Drafts
INBOX

But in sogo webmail "Other Users" folder still appears, with same error in sogo logs when I select it ("Mailbox doesn't exist: Shared").

Regarding ActiveSync issue, it's still there, Shared is still in the initial FolderSync response :

     <Add>
       <ServerId>
       'mail%2FShared'
       </ServerId>
       <ParentId>
       '0'
       </ParentId>
       <DisplayName>
       'Autres utilisateurs'
       </DisplayName>
       <Type>
       '12'
       </Type>
     </Add>


iOS device still request a Sync command every second for Shared...
(0012273)
tfu (reporter)
2017-09-07 07:07

I cannot reproduce the your problem.
What is your dovecot version?
Please show me your configure regarding
namespace = {
type = shared
...
}

What is the output of the IMAP command NAMESPACE?
(0012275)
bgaussen (reporter)
2017-09-07 09:18

dovecot --version
2.2.31 (65cde28)

namespace {
    type = shared
    separator = /
    prefix = Shared/%%u/
    location = maildir:%%h/:INDEXPVT=~/Shared/%%u
    subscriptions = no
    list = children
}

A NAMESPACE
* NAMESPACE (("" "/")) (("Shared/" "/")) NIL


I'm trying to get more debug information in order to help you reproduce the issue if possible.
(0012299)
tfu (reporter)
2017-09-17 07:32

ImapDebugEnabled = YES; might help to find the problem.
(0012345)
bgaussen (reporter)
2017-09-29 10:09

Hi,

In order to get a normal behaviour I disabled Shared namespace in dovecot.
However I enabled it again to test with iOS11 and I still have the same issue, a lot of requests from all my iOS end-user devices (iOS 10 and iOS 11) requesting for Shared mailbox. Note that the issue does not appear as soon as I told. It may take some time before entering the request loop.

Here are the sogo logs with ImaDebugEnabled for one of those many requests :

 Sep 29 16:06:02 6afa504482f8 S[0x558ad9160300]: * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE STARTTLS LOGINDISABLED] Dovecot ready.
Sep 29 16:06:02 6afa504482f8 C[0x558ad9154f50]: 1 STARTTLS
Sep 29 16:06:02 6afa504482f8 S[0x558ad9160300]: 1 OK Begin TLS negotiation now.
Sep 29 16:06:02 6afa504482f8 C[0x558ad9154f50]: 2 login "XXXXXXXXXXXX" "XXXXXXXX"
Sep 29 16:06:02 6afa504482f8 S[0x558ad944f5d0]: 2 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE COMPRESS=DEFLATE QUOTA ACL RIGHTS=texk] Logged in
Sep 29 16:06:02 6afa504482f8 C[0x558ad9154f50]: 3 capability
Sep 29 16:06:02 6afa504482f8 S[0x558ad944f5d0]: * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUSep 29 16:06:02 sogod [188]: 83.197.145.212 "POST /SOGo/Microsoft-Server-ActiveSync?User=ben@trez.org&DeviceId=QA3BBMUC3D51T1R5TMGCFO5DJO&DeviceType=iPhone&Cmd=Sync HTTP/1.0" 200 0/65 0.426 - - 0
Sep 29 16:06:03 6afa504482f8 sogod [188]: <0x0x558ad9236440[NGImap4Client]> TLS started successfully.
Sep 29 16:06:03 6afa504482f8 S BINARY MOVE COMPRESS=DEFLATE QUOTA ACL RIGHTS=texk
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 3 OK Capability completed (0.001 + 0.044 + 0.044 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 4 ID ("x-originating-ip" "xxx.xxx.xxx.xxx")
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * ID ("name" "Dovecot")
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 4 OK ID completed (0.001 + 0.044 + 0.043 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 5 LIST "" ""
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\Noselect) "/" ""
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 5 OK List completed (0.001 + 0.044 + 0.043 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 6 LIST "" "*"
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Sent) "/" Sent
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Trash) "/" Trash
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Archive) "/" Archive
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Junk) "/" Junk
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Personnel
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Drafts) "/" Drafts
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" INBOX
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 6 OK List completed (0.001 + 0.044 + 0.044 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 7 namespace
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * NAMESPACE (("" "/")) (("Shared/" "/")) NIL
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 7 OK Namespace completed (0.001 + 0.044 + 0.043 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 8 LIST "" "*"
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Sent) "/" Sent
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Trash) "/" Trash
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Archive) "/" Archive
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Junk) "/" Junk
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Personnel
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren \Drafts) "/" Drafts
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" INBOX
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 8 OK List completed (0.001 + 0.044 + 0.043 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 9 list "" "*" return (status (x-guid) children)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Sent
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Sent (X-GUID b2a8e2174f9a6a59ef000000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Trash
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Trash (X-GUID c0c53b06906f6b5901010000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Archive
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Archive (X-GUID 03a1c906f2516d5921030000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Junk
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Junk (X-GUID fd5c2226ac6c6b5946000000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Personnel
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Personnel (X-GUID 78378a1b2b9d6a5936010000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" Drafts
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS Drafts (X-GUID 6b9e530731297a5930010000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * LIST (\HasNoChildren) "/" INBOX
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * STATUS INBOX (X-GUID 614be7007a976a595f000000c147d4d9)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 9 OK List completed (0.005 + 0.044 + 0.048 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 10 status "Shared" (UIDVALIDITY)
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: 10 NO Mailbox doesn't exist: Shared (0.001 + 0.000 secs).
Sep 29 16:06:03 6afa504482f8 C[0x558ad9154f50]: 11 logout
Sep 29 16:06:03 6afa504482f8 S[0x558ad944f5d0]: * BYE Logging out


Ben.
(0012346)
tfu (reporter)
2017-10-01 09:34

I still cannot figure out what's wrong on your side and I'm still not able to reproduce the behavior in my environment.

Can you provide me a sogo.log with ImapDebugEnabled = YES AND SOGoEASDebugEnabled = YES AND NGImap4ConnectionCacheDebugEnabled = YES including the first FolderSync response until the loop stats?
(0012347)
tfu (reporter)
2017-10-01 15:29

You can ignore my previous request, I identified by bug.

I can reproduce the problem when I set SOGoIMAPServer = "imaps://127.0.0.1/?tls=YES"; instead of SOGoIMAPServer = "imaps://127.0.0.1

urlString in _allFoldersFromNS (NGImap4Connection) is built like this: imaps://XXXXX%40XXXX.XXX@127.0.0.1/?tls=YESShared/

which is wrong ...
(0012349)
bgaussen (reporter)
2017-10-02 03:14

Hi

Thank you for the follow-up, and for finding the bug. Indeed I have the following log with NGImap4ConnectionCacheDebugEnabled during the loop :

 <0x0x561b7fb12f40[NGImap4Connection]> primaryFetchMailboxHierarchyForURL - cache miss for URL: imaps://xxx%40xxxx.xxx@dovecot/?tls=YESShared/


Regards,

Benoit.

- Related Changesets
sogo: master 9b20a837
Timestamp: 2017-10-03 09:13:56
Author: ludovic
Details ] Diff ]
(fix) properly extract IMAP folder name (fixes 0004275)
mod - SoObjects/Mailer/SOGoMailAccount.m Diff ] File ]
sogo: v2 1085e55f
Timestamp: 2017-10-03 09:13:56
Author: ludovic
Details ] Diff ]
(fix) properly extract IMAP folder name (fixes 0004275)
mod - SoObjects/Mailer/SOGoMailAccount.m Diff ] File ]

- Issue History
Date Modified Username Field Change
2017-09-06 10:46 bgaussen New Issue
2017-09-06 11:51 tfu Note Added: 0012266
2017-09-06 11:53 bgaussen Note Added: 0012267
2017-09-06 12:20 tfu Note Added: 0012268
2017-09-06 15:43 bgaussen Note Added: 0012269
2017-09-07 07:07 tfu Note Added: 0012273
2017-09-07 09:18 bgaussen Note Added: 0012275
2017-09-17 07:32 tfu Note Added: 0012299
2017-09-29 10:09 bgaussen Note Added: 0012345
2017-10-01 09:34 tfu Note Added: 0012346
2017-10-01 15:29 tfu Note Added: 0012347
2017-10-02 03:14 bgaussen Note Added: 0012349
2017-10-03 09:15 ludovic Changeset attached => sogo master 9b20a837
2017-10-03 09:15 ludovic Assigned To => ludovic
2017-10-03 09:15 ludovic Resolution open => fixed
2017-10-03 09:15 ludovic Changeset attached => sogo v2 1085e55f
2017-10-11 11:19 ludovic Status new => resolved
2017-10-11 11:19 ludovic Fixed in Version => 3.2.11


Copyright © 2000 - 2017 MantisBT Team
Powered by Mantis Bugtracker