Problems with z-push, Zarafa and Android 6



  • Setup:
    Host 1: Zarafa 7.2.4 on Debian 7
    Host 2: Apache Websver 2.4 running z-push 2.3.6 with z-push-backend-kopano

    I’m trying to make it work for the first time.

    When I set up my Sony Xperia Z3 with Android 6.0.1, I can go through the Mobile setup procedure. After (sucessfully) logging in using Exchange ActiveSync, I have to answer multiple question, for example I have to allow remove wiping, disableing the camera and so on. I also see in the Debug log reading my mailbox folders (my mailbox is huge!).

    After some time of syncing, my mobile says “Syncronisation: The account could not be created. Try again later” (Das Konto konnte nicht erstellt werden. Versuchen Sie es später erneut)

    What can I do?


  • Kopano

    Hi itserv,

    I moved the topic because Zarafa and Kopano are the same backend.

    How long does the FolderSync request take (you can see that information on INFO log level)? Android devices have a hard-coded timeout of 30 seconds and if the request takes longer than that, they will start over.

    How big is your mailbox? Are you syncing everything or do you limit the data to 1 week or 1 month etc?

    Are there any errors in Z-Push and / or apache logs?

    Manfred



  • The FolderSync Request, if I get you right, takes log lines like these:

    26/05/2017 15:39:26 [ 7635] [DEBUG] [pbauer] HierarchyCache: AddFolder() serverid: Udaf36 displayname: RVI
    26/05/2017 15:39:26 [ 7632] [DEBUG] [pbauer] HierarchyCache: AddFolder() serverid: U172ec displayname: Immobilie
    26/05/2017 15:39:26 [32638] [DEBUG] [pbauer] HierarchyCache: AddFolder() serverid: Ub8da7 displayname: DLH
    26/05/2017 15:39:26 [17780] [DEBUG] [pbauer] HierarchyCache: AddFolder() serverid: U29d03 displayname: Gesendete Objekte

    The errorlog contains lines like these:

    26/05/2017 15:36:28 [23923] [FATAL] [pbauer] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command
    26/05/2017 15:37:16 [16492] [FATAL] [pbauer] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command
    26/05/2017 15:37:22 [16019] [FATAL] [pbauer] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command

    It’s very hard to decide how long the foldersync runs, as it is started over and over again, reading more and more of my mailbox - even when I disable E-Mail sync.

    In total, a FolderSync takes more than 10 Minutes, I’d guess.

    The total size of my mailbox (reported by Outlook) is 3.2GB, but I could experiment with a much smaller mbox.

    In the meantime, I could manage to have the account created by tapping on “create another account” while the one created is still syncing. But that’s unstable.



  • Well, it looks with a smaller mailbox with far less objects, it seems to work.

    I will do further investigation.


  • Kopano

    Hi itserv,

    there’s a log line which says how long a request took.

    25/05/2017 16:39:03 [11525] [ INFO] [samsung] cmd=‘FolderSync’ memory=‘2.10 MiB/4.00 MiB’ time=‘0.24s’ devType=‘SAMSUNGSMGF’ devId=‘123’ getUser=‘samsung’ from=‘192.168.1.73’ idle=‘0s’ version=‘develop-2.3.4beta1-261-g0e4a1a3’ method=‘POST’ httpcode=‘200’

    It’s right before the “-------- End”.
    Manfred



  • Manfred,

    first, thank you for your help.

    next, I made z-push work with a test user using the same (default, except for the MAPI_SERVER setting) configuration I struggled with. So I can clearly say: z-push works with my setup for a small account.

    Now, I switch to my production account I run into trouble with. I’m only interested in syncing contacts and appointments. I don’t want to sync my 3.2 GB Mailbox with hundreds of folders and subfolders.

    So I cleaned up my device (removed ActiveSync account, stopped Calendar and cleared it’s data, and did the same for Contacts). Then, I added my production account.

    The settings become checked, and then I reach the “Sychronisation” page. I keep “push” activated, but disable E-Mail-sync, Task-Sync and Download attachments. Only Contacs and Calendar stays checked.

    After saving the account as a new name , I have to confirm the security settings (remote wipe and so on), and FolderSync starts

    28/05/2017 12:12:41 [ 1789] [DEBUG] [user.name] cmd='FolderSync' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' version='2.3.6+0' method='POST'
    

    Now, looking in what’s going on by opening the new account and seeing a sync is in process, I see an E-Mail-Sync running (I definetly disabled E-mail sync), and after a few minutes, the device says “E-Mail sync OFF”, but the server is still doing a foldersync.

    Looking at the duration(s) a folderSync takes, I see multiple lines:

    28/05/2017 12:15:53 [ 1791] [ INFO] [user.name] cmd='FolderSync' memory='7.77 MiB/8.25 MiB' time='222.17s' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' idle='0s' version='2.3.6+0' method='POST' httpcode='200'
    
    28/05/2017 12:16:12 [ 1789] [ INFO] [user.name] cmd='FolderSync' memory='7.63 MiB/8.25 MiB' time='210.89s' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' idle='0s' version='2.3.6+0' method='POST' httpcode='200'
    
    28/05/2017 12:16:41 [ 6951] [ INFO] [user.name] cmd='FolderSync' memory='7.63 MiB/8.25 MiB' time='209.26s' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' idle='0s' version='2.3.6+0' method='POST' httpcode='200'
    
    28/05/2017 12:18:34 [ 1788] [ INFO] [user.name] cmd='FolderSync' memory='7.63 MiB/8.25 MiB' time='229.46s' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' idle='0s' version='2.3.6+0' method='POST' httpcode='200'
    

    All of these FolderSyncs do stuff like these:

    28/05/2017 12:18:30 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Uaadfb displayname: Internet Access
    28/05/2017 12:18:30 [ 1788] [DEBUG] [user.name] ASDevice->GetFolderIdForBackendId(): generated new folderid 'U286b1' for backend-folderid 'e145b78f5634408f9a731e5aa829b81295be0c000000'
    28/05/2017 12:18:30 [ 1788] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U286b1 displayname: 01-xx Lagento Sanitär
    28/05/2017 12:18:31 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Ubee1d displayname: Telefonie
    28/05/2017 12:18:31 [ 1788] [DEBUG] [user.name] ASDevice->GetFolderIdForBackendId(): generated new folderid 'U4a4aa' for backend-folderid 'e145b78f5634408f9a731e5aa829b812638205000000'
    28/05/2017 12:18:31 [ 1788] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:18:31 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U281c1 displayname: AVIRA
    

    Then, the log entries change:

    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 472
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] FileStateMachine->SetState() written 123855 bytes on file: '/var/lib/z-push/5/1/androidc118021415-da1bab6c-6957-486b-82ea-cdbcb60eaba2-hc-1'
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] FileStateMachine->SetState() written 15 bytes on file: '/var/lib/z-push/5/1/androidc118021415-da1bab6c-6957-486b-82ea-cdbcb60eaba2-1'
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] SyncCollections::InvalidatePingableFlags(): Invalidating now
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] FileStateMachine->SetState() written 379 bytes on file: '/var/lib/z-push/5/1/androidc118021415-da1bab6c-6957-486b-82ea-cdbcb60eaba2-fd'
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] WBXMLEncoder->endTag() WBXML output completed
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] DeviceManager->Save(): Device data changed
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] FileStateMachine->SetState() written 40544 bytes on file: '/var/lib/z-push/5/1/androidc118021415-devicedata'
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] DeviceManager->Save(): Device data saved
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] LoopDetection->ProcessLoopDetectionTerminate()
    28/05/2017 12:18:34 [ 1788] [ INFO] [user.name] cmd='FolderSync' memory='7.63 MiB/8.25 MiB' time='229.46s' devType='SonyD' devId='androidc118021415' getUser='user.name' from='x.x.x.x' idle='0s' version='2.3.6+0' method='POST' httpcode='200'
    28/05/2017 12:18:34 [ 1788] [DEBUG] [user.name] -------- End
    28/05/2017 12:18:34 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U9b43e displayname: BrainBench
    28/05/2017 12:18:34 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Ue9e7a displayname: RedHat
    28/05/2017 12:18:35 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U7303f displayname: Oracle
    28/05/2017 12:18:36 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Ubde87 displayname: Solaris 11 Upgrade
    28/05/2017 12:18:36 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U12c5f displayname: FireBrand
    28/05/2017 12:18:37 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Ub04f5 displayname: Maxpert
    28/05/2017 12:18:38 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Uec122 displayname: _Wärmepumpe
    28/05/2017 12:18:39 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U3ea7e displayname: Deutsche Bank Darlehen
    28/05/2017 12:18:40 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U32790 displayname: PV-Anlage
    28/05/2017 12:18:40 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U6f222 displayname: Gold- und Silber
    28/05/2017 12:18:41 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Ue0d61 displayname: 2013
    

    So, I’d think, the first FolderSync starts at 12:15:53 and ends at 12:18:34, but after this, FolderSyncs are run again and again.

    And it adds the same objects over and over again:

    root@border:/var/log/z-push# grep MultiVendor z-push.log
    28/05/2017 12:15:51 [ 1791] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:16:09 [ 1789] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:16:38 [ 6951] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:18:31 [ 1788] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:22:20 [ 1856] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:27:37 [ 8398] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:36:14 [14814] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:40:52 [14814] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:41:08 [14813] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:41:56 [18297] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:42:26 [14815] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:43:47 [ 1806] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:44:30 [ 1868] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:46:55 [19175] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    28/05/2017 12:47:39 [18715] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4a4aa displayname: MultiVendor
    

    When I manually start a resync on the mobile, z-push seems to scan through my mail folders over and over again:

    28/05/2017 12:41:44 [14815] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U52475 displayname: 06-09 Platinen
    28/05/2017 12:41:44 [18297] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U9dff3 displayname: 05-16 Spiel
    28/05/2017 12:41:44 [ 1806] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U74097 displayname: BMC
    28/05/2017 12:41:44 [ 1868] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U4bb12 displayname: _ALLE
    28/05/2017 12:41:44 [14815] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U8a6af displayname: 06-10 Kunststoffpinzetten
    28/05/2017 12:41:44 [18297] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U7de63 displayname: 05-21 Amazon
    28/05/2017 12:41:44 [ 1806] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: U55ed9 displayname: Fujitsu
    28/05/2017 12:41:45 [14815] [DEBUG] [user.name] HierarchyCache: AddFolder() serverid: Uef33d displayname: 06-23 Druckerfolien
    

    The logs stop growing 10 minutes after I manually started the sync
    While the logs on the server still grow, my device claims to have finished syncing. Last successful sync: 28.05.17 12:11 (this is before the initial FolderSync). The clocks on the server and the mobile are in sync.

    There is a 2MBit DSL line between the zarafa server and z-push. Could it help if I put them on the same host?



  • OK, I did a quick re-installation of the software directly on my Zarafa server, and connected my mobile device directly to this server, and everything works quick and flawless.

    There seems to be a problem with the timing, I think.

    I will do further investigation and come back here to report, but please give me a few days as I can only work on this during my spare time.



  • OK, i did now change the setup in this way:

    Webserver & Apache reverseProxy---->======2MBit DSL=====—> z-push&zarafa.

    This works well, even with my 3GB zarafa account.

    My first setup which failed was

    Webserver & z-push ---->======2MBit DSL=====—> zarafa.

    Obvisiusly, it’s very important that z-push and zarafa can talk in high speed with each other. Timing on FolderSync seems to be an issue.

    All works well at my side now. Thank you for your support.


  • Kopano

    Well, in one of yours posts it says that your foldersync takes 220 seconds. That’s way too long, especially as Androids have a hard timeout of 30 seconds (for the request to end).

    Improving speed between components is definetely the best way to deal with that. You can also enable the USE_PARTIAL_FOLDERSYNC feature in your config that actively terminates your requests if they would take too long.

    Good that it’s solved.

    Cheers,
    Sebastian


Log in to reply
 

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.