Z-Push Version 2.4.3+0-0 w/ Kopano stops working (after 'FolderSync')

Hi guys,

after being a happy(!! :) z-push user for several years now, I’m having trouble with current version 2.4.3 with all of my AS endpoints with multiple accounts:
iPhones and iPads with 11.4 stopped syncing
Android devices (Samsung Tab + Motorola handset) no longer sync
Outlook 2016 doesn’t sync any more

WebApp and Kopano Desktop client are totally fine btw.

So, I disabled provisioning, created a new testuser and a new mailbox profile on an iPhone, created several subfolders in the mailbox and enabled WBXML-Debuglogs, but can’t pinpoint the error. Can you figure out what’s wrong? Here’s the log:

10/07/2018 17:00:55 [  669] [DEBUG] -------- Start
10/07/2018 17:00:55 [  669] [DEBUG] cmd='FolderSync' devType='iPhone' devId='vb059utua52alc4er1118gbtng' getUser='testuser' from='192.168.2.35' version='2.4.3+0-0' method='POST'
10/07/2018 17:00:55 [  669] [DEBUG] Used timezone 'Europe/Berlin'
10/07/2018 17:00:55 [  669] [DEBUG] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 5.5.9-1ubuntu4.25
10/07/2018 17:00:55 [  669] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::CommandNeedsAuthentication(9): true
10/07/2018 17:00:55 [  669] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'testuser'..
10/07/2018 17:00:55 [  669] [ INFO] StateNotFoundException: FileStateMachine->GetStateHash(): Could not locate state '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-devicedata' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:93
10/07/2018 17:00:55 [  669] [DEBUG] TopCollector(): Initialized mutexid Resource id #57 and memid Resource id #58.
10/07/2018 17:00:55 [  669] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
10/07/2018 17:00:55 [  669] [DEBUG] LoopDetection(): Initialized mutexid Resource id #62 and memid Resource id #63.
10/07/2018 17:00:55 [  669] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::HierarchyCommand(9): true
10/07/2018 17:00:55 [  669] [DEBUG] KopanoBackend->openMessageStore('testuser'): Found 'DEFAULT' store: 'Resource id #70'
10/07/2018 17:00:55 [  669] [DEBUG] KopanoBackend->Logon(): User 'testuser' is authenticated
10/07/2018 17:00:55 [  669] [DEBUG] Store supports properties containing Unicode characters.
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1
10/07/2018 17:00:55 [  669] [ INFO] Announcing latest AS version to device: 12.0,12.1,14.0,14.1
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::CommandNeedsPlainInput(9): false
10/07/2018 17:00:55 [  669] [WBXML] I  <FolderHierarchy:FolderSync>
10/07/2018 17:00:55 [  669] [WBXML] I   <FolderHierarchy:SyncKey>
10/07/2018 17:00:55 [  669] [WBXML] I    0
10/07/2018 17:00:55 [  669] [WBXML] I   </FolderHierarchy:SyncKey>
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1
10/07/2018 17:00:55 [  669] [DEBUG] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
10/07/2018 17:00:55 [  669] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
10/07/2018 17:00:55 [  669] [WBXML] I  </FolderHierarchy:FolderSync>
10/07/2018 17:00:55 [  669] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
10/07/2018 17:00:55 [  669] [DEBUG] ExportChangesICS->Config() initialized with state: 0x0000000000000000
10/07/2018 17:00:55 [  669] [DEBUG] ExportChangesICS->InitializeExporter() successfully. 0 changes ready to sync for 'hierarchy'.
10/07/2018 17:00:55 [  669] [WBXML] O  <FolderHierarchy:FolderSync>
10/07/2018 17:00:55 [  669] [WBXML] O   <FolderHierarchy:Status>
10/07/2018 17:00:55 [  669] [WBXML] O   1
10/07/2018 17:00:55 [  669] [WBXML] O   </FolderHierarchy:Status>
10/07/2018 17:00:55 [  669] [WBXML] O   <FolderHierarchy:SyncKey>
10/07/2018 17:00:55 [  669] [WBXML] O   {f440ef41-aad7-4f26-8ce0-c7069af1a0df}1
10/07/2018 17:00:55 [  669] [WBXML] O   </FolderHierarchy:SyncKey>
10/07/2018 17:00:55 [  669] [WBXML] O   <FolderHierarchy:Changes>
10/07/2018 17:00:55 [  669] [WBXML] O    <FolderHierarchy:Count>
10/07/2018 17:00:55 [  669] [WBXML] O    0
10/07/2018 17:00:55 [  669] [WBXML] O    </FolderHierarchy:Count>
10/07/2018 17:00:55 [  669] [WBXML] O   </FolderHierarchy:Changes>
10/07/2018 17:00:55 [  669] [DEBUG] DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders
10/07/2018 17:00:55 [  669] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
10/07/2018 17:00:55 [  669] [DEBUG] StateManager::linkState(#ASDevice, 'f440ef41-aad7-4f26-8ce0-c7069af1a0df','HierarchyCache'): linked to uuid 'f440ef41-aad7-4f26-8ce0-c7069af1a0df'.
10/07/2018 17:00:55 [  669] [DEBUG] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
10/07/2018 17:00:55 [  669] [DEBUG] FileStateMachine->SetState() written 58 bytes on file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-f440ef41-aad7-4f26-8ce0-c7069af1a0df-hc-1'
10/07/2018 17:00:55 [  669] [DEBUG] FileStateMachine->SetState() written 15 bytes on file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-f440ef41-aad7-4f26-8ce0-c7069af1a0df-1'
10/07/2018 17:00:55 [  669] [DEBUG] SyncCollections::InvalidatePingableFlags(): Invalidating now
10/07/2018 17:00:55 [  669] [DEBUG] FileStateMachine->SetState() written 372 bytes on file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-f440ef41-aad7-4f26-8ce0-c7069af1a0df-fd'
10/07/2018 17:00:55 [  669] [WBXML] O  </FolderHierarchy:FolderSync>
10/07/2018 17:00:55 [  669] [DEBUG] WBXMLEncoder->endTag() WBXML output completed
10/07/2018 17:00:55 [  669] [WBXML] WBXML-OUT: AwFqAAAHVkwDMQABUgN7ZjQ0MGVmNDEtYWFkNy00ZjI2LThjZTAtYzcwNjlhZjFhMGRmfTEAAU5XAzAAAQEB
10/07/2018 17:00:55 [  669] [WBXML] WBXML-IN : AwFqAAAHVlIDMAABAQ==
10/07/2018 17:00:55 [  669] [DEBUG] Special header: MS-ASProtocolVersions: 12.0,12.1,14.0,14.1
10/07/2018 17:00:55 [  669] [DEBUG] Special header: MS-ASProtocolCommands: Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
10/07/2018 17:00:55 [  669] [DEBUG] DeviceManager->Save(): Device data changed
10/07/2018 17:00:55 [  669] [ INFO] Linking device ID 'vb059utua52alc4er1118gbtng' to user 'testuser'
10/07/2018 17:00:55 [  669] [DEBUG] SimpleMutex(): Initialized mutexid Resource id #199 and memid Resource id #200.
10/07/2018 17:00:55 [  669] [DEBUG] SimpleMutex initialised with IPC provider 'IpcSharedMemoryProvider' with type '5173'
10/07/2018 17:00:55 [  669] [DEBUG] FileStateMachine->LinkUserDevice(): wrote 65 bytes to users file
10/07/2018 17:00:55 [  669] [DEBUG] FileStateMachine->SetState() written 540 bytes on file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-devicedata'
10/07/2018 17:00:55 [  669] [DEBUG] DeviceManager->Save(): Device data saved
10/07/2018 17:00:55 [  669] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate()
10/07/2018 17:00:55 [  669] [ INFO] cmd='FolderSync' memory='5.55 MiB/6.00 MiB' time='0.08s' devType='iPhone' devId='vb059utua52alc4er1118gbtng' getUser='testuser' from='192.168.2.35' idle='0s' version='2.4.3+0-0' method='POST' httpcode='200'
10/07/2018 17:00:55 [  669] [DEBUG] -------- End

The mailbox folders never show up on the iPhone, the calendar isn’t synced at all and the contacts are missing as well (not really a surprise if FolderSync fails). The iPhone says “Account error, connection to server failed” after a while. The Apache error log is empty, server’s an Ubuntu server 14.04 LTS.

Thanks in advance.

Hi matban,

did you also update KC together with Z-Push? Is webapp on the same server as Z-Push? Is there anything in the server.log of kopano?

Manfred

Hi Manfred,

thanks for your help. Yes, KC has been upgraded recently to 8.6.80.129-0+5.1 (all KC components are at this version), webapp 3.4.11.1346+767.1 is running on the same host along with z-push 2.4.3+0-0. All 3 solutions are installed on 1 machine, the webserver is an Apache 2.4.7-1ubuntu4.20.

The server.log of Kopano shows nothing special, even when started with loglevel ‘6’.

Hi matban,

maybe an update to iOS 11.4.1 will help. This update includes fixes for ActiveSync. Look here: https://support.apple.com/en-us/ht208067#1141

Martin

Hi matban,

how exactly have you installed KC?

Manfred

@martin I hoped this as well - unfortunately, the problem remains. Please note: My android-based devices don’t sync either. They seem to have the same problem: FolderSync returns 0 items for any user.

Hi Manfred,
since the swap from zarafa I simply downloaded the correct tarball here (https://download.kopano.io/community/core:/), there used to be a Ubuntu 14_04_amd64 archive.

After un-taring, I always used to run:
dpkg -i *.deb
apt-get install -f
dpkg -i *.deb (again)

Hi @Manfred, @Martin,

thanks for your support, very appreciated. After fiddling around desperately and getting nowhere, I did a release-upgrade to the next LTS version (Ubuntu Server 16.04). I wanted PHP7 anyway. ;-)

After upgrading KC + Z-Push to the corresponding 16.04 versions (KC 8.6.80.1248-0+176.1 and Z-Push 2.4.3+0-0), we are finally able to ActiveSync mailbox contents again:

12/07/2018 15:05:39 [10202] [DEBUG] [testuser] -------- Start
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] cmd='FolderSync' devType='iPhone' devId='vb059utua52alc4er1118gbtng' getUser='testuser' from='192.168.2.35' version='2.4.3+0-0' method='POST'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] Used timezone 'Europe/Berlin'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 7.0.30-0ubuntu0.16.04.1
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] Request::ProcessHeaders() ASVersion: 14.1
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] ZPush::CommandNeedsAuthentication(9): true
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] KopanoBackend->Logon(): Trying to authenticate user 'testuser'..
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] FileStateMachine->GetState() read '1618' bytes from file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-devicedata'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] ASDevice data loaded for user: 'testuser'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18.
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22.
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
12/07/2018 15:05:39 [10202] [DEBUG] [testuser] ZPush::HierarchyCommand(9): true
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] KopanoBackend->openMessageStore('testuser'): Found 'DEFAULT' store: 'Resource id #28'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] KopanoBackend->Logon(): User 'testuser' is authenticated
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] Store supports properties containing Unicode characters.
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ZPush::CommandNeedsPlainInput(9): false
12/07/2018 15:05:40 [10202] [WBXML] [testuser] I  <FolderHierarchy:FolderSync>
12/07/2018 15:05:40 [10202] [WBXML] [testuser] I   <FolderHierarchy:SyncKey>
12/07/2018 15:05:40 [10202] [WBXML] [testuser] I    0
12/07/2018 15:05:40 [10202] [WBXML] [testuser] I   </FolderHierarchy:SyncKey>
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] FileStateMachine->GetState() read '372' bytes from file: '/var/lib/z-push/g/n/vb059utua52alc4er1118gbtng-64460ba0-a83f-4776-9d6d-da3691a6ae8b-fd'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] SyncParameters->UseCPO('DEFAULT')
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
12/07/2018 15:05:40 [10202] [WBXML] [testuser] I  </FolderHierarchy:FolderSync>
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ExportChangesICS->Config() initialized with state: 0x0000000000000000
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ExportChangesICS->InitializeExporter() successfully. 34 changes ready to sync for 'hierarchy'.
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] MAPIProvider->GetStoreProps(): Getting store properties.
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'Ud2978' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f9260000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] MAPIProvider->getInboxProps(): Getting inbox properties.
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: Ud2978 displayname: Inbox
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'Ucca7a' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f9270000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: Ucca7a displayname: Outbox
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'U5f5f5' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f9280000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: U5f5f5 displayname: Deleted Items
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'U9ed18' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f9290000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: U9ed18 displayname: Sent Items
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'U5cacb' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f92a0000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: U5cacb displayname: Contacts
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] ASDevice->GetFolderIdForBackendId(): generated new folderid 'Uc54ed' for backend-folderid '7d36f4f9458647ac899bc632b22eb8f92b0000000000'
12/07/2018 15:05:40 [10202] [DEBUG] [testuser] HierarchyCache: AddFolder() serverid: Uc54ed displayname: Calendar

[...]

Hooray!

Best regards
MatBan

Hi MatBan,

good to hear it works now. To upgrade the OS would have been my next suggestion as there aren’t community packages for Ubuntu 14 anymore.

Manfred