Problems with z-push, Zarafa and Android 6

itserv

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?

Manfred

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

itserv

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.

itserv

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

I will do further investigation.

Manfred

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

itserv

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?

itserv

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.

itserv

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.

Sebastian

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