View Issue Details

Related ChangesetsJump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0004275SOGoActiveSyncpublic2017-09-06 14:462017-10-11 15:20
Reporterbgaussen Assigned Toludovic  
PriorityhighSeveritymajorReproducibilityalways
Status resolvedResolutionfixed 
PlatformAppleOSiOSOS Version10
Product Version3.2.10 
Fixed in Version4.0.0 
Summary0004275: EAS Sync requests for Shared folder every second
Description

Digging 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 Information

sogo+dovecot part of mailcow

TagsNo tags attached.

Activities

tfu

tfu

2017-09-06 15:51

reporter   ~0012266

What shows following command on your server?
doveadm mailbox list -u user
bgaussen

bgaussen

2017-09-06 15:53

reporter   ~0012267

doveadm mailbox list -u xxx@xxx.xxx

Sent
Trash
Archive
Junk
Drafts
Shared
INBOX
tfu

tfu

2017-09-06 16:20

reporter   ~0012268

Try to set

list = children

for namespace type=shared.
bgaussen

bgaussen

2017-09-06 19:43

reporter   ~0012269

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...
tfu

tfu

2017-09-07 11:07

reporter   ~0012273

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?
bgaussen

bgaussen

2017-09-07 13:18

reporter   ~0012275

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.
tfu

tfu

2017-09-17 11:32

reporter   ~0012299

ImapDebugEnabled = YES; might help to find the problem.
bgaussen

bgaussen

2017-09-29 14:09

reporter   ~0012345

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.
tfu

tfu

2017-10-01 13:34

reporter   ~0012346

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?
tfu

tfu

2017-10-01 19:29

reporter   ~0012347

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 ...
bgaussen

bgaussen

2017-10-02 07:14

reporter   ~0012349

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

2017-10-03 09:13

ludovic


Details Diff		 (fix) properly extract IMAP folder name (fixes 0004275) Affected Issues
0004275
mod - SoObjects/Mailer/SOGoMailAccount.m Diff File

sogo: v2 1085e55f

2017-10-03 09:13

ludovic


Details Diff		 (fix) properly extract IMAP folder name (fixes 0004275) Affected Issues
0004275
mod - SoObjects/Mailer/SOGoMailAccount.m Diff File

Issue History

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