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 moreWebApp 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) -
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