IOS Devices dont getting synced anymore since z-push/kopano Update
-
Hi Manfred
i upgraded kopano and z-push via the Ubuntu 16.04 Repositorys.
The Problem starting with z-push Version 2.3.8. On Kopano Side i cannot remember the Version but it was working with Kopano 5.4.0I tried different Things:
I upgraded without touching state Folder or anything else on z-push Side.
The Ios Devices are on 11.2.6.
For Troubleshoting i tried everything include wipeing the Device I also recreated couple of Times the Profils on the Phones without Success.
On z-push Side i tried :
z-push-admin -a remove -u usera
and
z-push-admin with clearloop and fixstates.When i clear the Systemwideloop the folowing is shown inside the z-push error log:
21/03/2018 09:02:21 [21147] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:22 [22016] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:23 [22952] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:26 [22068] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:27 [22958] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:28 [22016] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:29 [22952] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:31 [22471] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:33 [21531] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:35 [22958] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:37 [22016] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:38 [22952] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:40 [22471] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:41 [21531] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:43 [22958] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:45 [20468] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:47 [20510] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:49 [21147] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:50 [22068] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:52 [22958] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:54 [20468] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:55 [20510] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:57 [21147] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:02:59 [22068] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:03:00 [22958] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:03:02 [20468] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:03:03 [20510] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:03:05 [21147] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:03:06 [22068] [WARN] [usera] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict 21/03/2018 09:14:21 [23903] [FATAL] [usera] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 21/03/2018 09:14:21 [23892] [FATAL] [usera] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 21/03/2018 09:14:21 [22016] [FATAL] [usera] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 21/03/2018 09:14:22 [24030] [FATAL] [usera] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 21/03/2018 09:14:22 [24030] [WARN] [usera] The store is not available. It is not possible to remove search folder with pid 23903 21/03/2018 09:14:22 [22016] [FATAL] [usera] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command_(ProvisioningRequiredException) - Retry after sending a PROVISION command 21/03/2018 09:14:22 [22016] [WARN] [usera] The store is not available. It is not possible to remove search folder with pid 23892 21/03/2018 09:14:22 [24030] [FATAL] [usera] Excepti 21/03/2018 09:14:22 [24030] [WARN] [usera] The store is not available. It is not possible to remove search folder with pid 22016 21/03/2018 11:14:01 [22471] [WARN] [usera] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF80040116 - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230
-
Hi Stefan,
are all the iOS devices affected by this? Are there other devices connected (Androids, Windows Phones, Outlook via ActiveSync)?
Have you restarted apache after Kopano update? Are you able to open the emails in the webapp for this user?
Manfred
-
Hi Manfred,
yes all ios devices. I cross checked with Microsoft Outlook via ActiveSync. Same Problem !
Via Kopano Webmail it is working great.
Yes i restarted all relevant Services and the Server self multiple Times.BR Stefan
-
Hi Stefan,
can you post the full WBXML log since the initial FolderSync for one of the devices?
Manfred
-
you can download the logfile here:
https://brockz.dyndns.tv/index.php/s/5LHTrrDlVibsoTG -
Hi Stefan,
Were you switching between sql states and file states?
The Kopano version in the z-push.log is different from what you posted here. Are you using KC nightly builds?
Are there any errors in server.log of kopano?As first action I suggest to start with a clean Z-Push installation and configuration, remove all the states, execute clearloops with z-push-admin, remove profile from the device and create a profile again.
If the above doesn’t help, try downgrading KC to 8.5.5.0.
Manfred
-
Hello Manfred
for testing purpose i switched to sql states one time. Without Success. Problem still exists.
I reinstalled z-pusg acouple of Times new wihtout Success.
I try it again to reinstall it and coming back here with my findings. -
Hello!
I run into same problem after updating kopanocore to latest master from repository and z-push from 2.3.9 to 2.4.0.
I am running a gentoo server and I’m compiling from source.First I tried downgrading z-push to 2.3.9 first but that didn’t help.
After switiching kopanocore from master to 8.6.x branch it was working again.
I switched to z-push 2.4.0 again afterwards - also without any issues.I haven’t checked which commit caused that problem, because I hadn’t time anymore…
-
How can i downgrade ?
Where can i find the 8.6.x Branch ?
I am on Kopano 8.6.80.3 an having the Problem -
Hi Stefan,
for the best practice for the downgrade you should ask Kopano Support. If you don’t have a Kopano subscription, try asking in the core subforum. There’s also a thread regarding Kopano rollback: https://forum.kopano.io/topic/327/kopano-core-rollback
Manfred
-
Cannot download kopano core-8.4.90 for ubuntu 16.04 x64 anymore. This was my last Working Version. :(
-
It seems, I have the same problem on my Google Pixel 2 on latest Kopano for UCS (Univention)
WebApp: 3.4.9.1330+53.1
Kopano Core: 8.5.5
Z-Push: 2.4.0+0-0I deleted the account on my mobil and deleted all related account data with z-push-admin, then I recreated the account on my mobile, it begun syncing and after several /usr/share/z-push/backend/kopano/mapiprovider.php:997 Undefined offset errors and some loop messages, z-push reportet the sync to be finished and my mobile still tries to sync all unsynced data without any new connection to the server.
Addendum: I did my fifth account recreation on my mobile and this time I didn’t activate downloading attachments via WLAN (wifi) and now it seemed to finally sync, but with a lot of the errors and warnings, mentioned above.
-
Hello
I Reinstalled z-Push 2.4 from The Repo (no tarball) fresh without success. Also the downgrade to kopano 8.5.5 didnt resvolve the issue.
Br Stefan
-
Hi Stefan,
is it still the same problem that the sync won’t complete? Can you post z-push-admin output for that device and user?
Manfred
-
Hello Manfred
here we go:
Synchronized devices of user: usera ----------------------------------------------------- DeviceId: xxxx Device type: iPhone UserAgent: Apple-iPhone9C4/1504.100 Device Model: iPhone9C4 Device friendly name: iPhone 7 Plus Device OS: iOS 11.2.6 15D100 Device OS Language: de-DE ActiveSync version: 14.1 First sync: 2018-03-23 07:21 Last sync: 2018-03-23 15:38 Sync Period: unlimited (0) Total folders: 26 Short folder Ids: Yes Synchronized folders: 6 (2 in progress) Synchronized data: Emails(2) Contacts Calendars Notes Tasks Synchronization progress: Folder: Inbox Sync: Synchronizing Status: 1% (559/40955) Folder: Sent Items Sync: Synchronizing Status: 3% (59/2068) Additional Folders: none Status: OK WipeRequest on: not set WipeRequest by: not set Wiped on: not set Policy name: default Attention needed: No errors known
No Success. Stucks since Hours… (Status)
-
Hi Stefan,
there are 40k emails in your inbox. Have you tried synchronising a shorter period of time? Are there any errors in z-push.log or server.log of kopano? Do you have another device to try to sync?
Manfred
-
Hi!
I have the same problem with upgrade 8.6, I deleted all devices and sync again, the result:
z-push-error.log:
29/04/2018 12:12:02 [12054] [FATAL] [ablanco] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 29/04/2018 12:13:07 [21942] [FATAL] [ablanco] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command
z-push-admin:
Synchronized devices of user: USER --------------------------------------------------- DeviceId: XXXXX Device type: iPad UserAgent: Apple-iPad4C2/1505.302 Device Model: iPad4C2 Device friendly name: iPad Air Device OS: iOS 11.3.1 15E302 Device OS Language: es ActiveSync version: 14.1 First sync: 2018-04-29 12:12 Last sync: 2018-04-29 12:12 Sync Period: unlimited (0) Total folders: 0 Short folder Ids: No Synchronized folders: 0 Synchronized data: None available Additional Folders: none Status: OK WipeRequest on: not set WipeRequest by: not set Wiped on: not set Policy name: default Attention needed: No errors known ----------------------------------------------------- DeviceId: XXXXXX Device type: iPhone UserAgent: Apple-iPhone9C3/1505.302 Device Model: iPhone9C3 Device friendly name: Negro iPhone 7 Device OS: iOS 11.3.1 15E302 Device OS Language: es-ES ActiveSync version: 14.1 First sync: 2018-04-29 12:13 Last sync: 2018-04-29 12:13 Sync Period: unlimited (0) Total folders: 0 Short folder Ids: No Synchronized folders: 0 Synchronized data: None available Additional Folders: none Status: OK WipeRequest on: not set WipeRequest by: not set Wiped on: not set Policy name: default Attention needed: No errors known
Thanks! :)
-
Hi ablanco,
how do you deleted all devices? With z-push-admin?
Please also post z-push.log at least at DEBUG level.
Have you tried removing the account on the device and adding it again?
Manfred
-
This post is deleted! -
Hi Manfred,
Yes I delete all devices with z-push-admin and remove the account on all devices.
The log at the same moment:
29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] -------- Start 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] cmd='FolderSync' devType='iPad' devId='XXXX' getUser='ablanco' from='77.228.72.112' version='2.4.1.beta1+3- 0' method='POST' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] Used timezone 'Europe/Madrid' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 5.5.9-1ubuntu4.24 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] Request::ProcessHeaders() ASVersion: 14.1 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] ZPush::CommandNeedsProvisioning(9): true 29/04/2018 12:12:02 [12054] [ INFO] [ablanco] StateNotFoundException: FileStateMachine->GetStateHash(): Could not locate state '/var/lib/z-push/g/y/appldmplk0dbf4yg- devicedata' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:93 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] TopCollector(): Initialized mutexid Resource id #58 and memid Resource id #59. 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] LoopDetection(): Initialized mutexid Resource id #63 and memid Resource id #64. 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] ZPush::HierarchyCommand(9): true 29/04/2018 12:12:02 [12054] [ INFO] [ablanco] StateNotFoundException: FileStateMachine->GetStateHash(): Could not locate state '/var/lib/z-push/g/y/appldmplk0dbf4yg- devicedata' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:93 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] DeviceManager->ProvisioningRequired('789513718') saved device key '-1': true 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] DeviceManager->getPolicyName(): determined policy name: 'default' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 29/04/2018 12:12:02 [12054] [ INFO] [ablanco] ProvisioningRequiredException: Retry after sending a PROVISION command - code: 0 - file: /usr/share/z-push/index.php:82 29/04/2018 12:12:02 [12054] [ INFO] [ablanco] User-agent: 'Apple-iPad4C2/1505.302' 29/04/2018 12:12:02 [12054] [FATAL] [ablanco] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] DeviceManager->Save(): Device data changed 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] LoopDetection->ProcessLoopDetectionTerminate() 29/04/2018 12:12:02 [12054] [ INFO] [ablanco] cmd='FolderSync' memory='4.91 MiB/5.25 MiB' time='0.04s' devType='iPad' devId='XXX' getUser='ablanco' from ='77.228.72.112' idle='0s' version='2.4.1.beta1+3-0' method='POST' httpcode='449' 29/04/2018 12:12:02 [12054] [DEBUG] [ablanco] -------- End 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] -------- Start 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] cmd='Provision' devType='iPad' devId='XXXX' getUser='ablanco' from='77.228.72.112' version='2.4.1.beta1+3-0 ' method='POST' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] Used timezone 'Europe/Madrid' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 5.5.9-1ubuntu4.24 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] Request::ProcessHeaders() ASVersion: 14.1 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ZPush::CommandNeedsProvisioning(20): false 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ZPush::CommandNeedsAuthentication(20): false 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] FileStateMachine->GetState() read '862' bytes from file: '/var/lib/z-push/g/y/appldmplk0dbf4yg-devicedata' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ASDevice data loaded for user: 'ablanco' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] TopCollector(): Initialized mutexid Resource id #58 and memid Resource id #59. 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] LoopDetection(): Initialized mutexid Resource id #63 and memid Resource id #64. 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ZPush::HierarchyCommand(20): false 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] ZPush::CommandNeedsPlainInput(20): false 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] RequestProcessor::HandleProvision(): Forcing delayed Authentication 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] KopanoBackend->Logon(): Trying to authenticate user 'ablanco'.. 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] KopanoBackend->openMessageStore('ablanco'): Found 'DEFAULT' store: 'Resource id #78' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] KopanoBackend->Logon(): User 'ablanco' is authenticated 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] Store supports properties containing Unicode characters. 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:Provision> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:Policies> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:Policy> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:PolicyType> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I MS-EAS-Provisioning-WBXML 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:PolicyType> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:PolicyKey> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I 195388125 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:PolicyKey> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I <Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I 1 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:Policy> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:Policies> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] I </Provision:Provision> 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] DeviceManager->SetPolicyKey('713581845') 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:Provision> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O 1 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:Policies> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:Policy> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:PolicyType> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O MS-EAS-Provisioning-WBXML 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:PolicyType> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O 1 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:Status> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O <Provision:PolicyKey> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O 713581845 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:PolicyKey> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:Policy> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:Policies> 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] O </Provision:Provision> 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] WBXMLEncoder->endTag() WBXML output completed 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] WBXML-OUT: AwFqAAAORUsDMQABRkdIA01TLUVBUy1Qcm92aXNpb25pbmctV0JYTUwAAUsDMQABSQM3MTM1ODE4NDUAAQEBAQ== 29/04/2018 12:12:08 [20278] [WBXML] [ablanco] WBXML-IN : AwFqAAAORUZHSANNUy1FQVMtUHJvdmlzaW9uaW5nLVdCWE1MAAFJAzE5NTM4ODEyNQABSwMxAAEBAQE= 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] DeviceManager->Save(): Device data changed 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] FileStateMachine->SetState() written 912 bytes on file: '/var/lib/z-push/g/y/appldmplk0dbf4yg-devicedata' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] DeviceManager->Save(): Device data saved 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] LoopDetection->ProcessLoopDetectionTerminate() 29/04/2018 12:12:08 [20278] [ INFO] [ablanco] cmd='Provision' memory='5.15 MiB/5.50 MiB' time='0.05s' devType='iPad' devId='XXXX' getUser='ablanco' from= '77.228.72.112' idle='0s' version='2.4.1.beta1+3-0' method='POST' httpcode='200' 29/04/2018 12:12:08 [20278] [DEBUG] [ablanco] -------- End 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] -------- Start 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] cmd='FolderSync' devType='iPad' devId='XXX' getUser='ablanco' from='77.228.72.112' version='2.4.1.beta1+3- 0' method='POST' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] Used timezone 'Europe/Madrid' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 5.5.9-1ubuntu4.24 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] Request::ProcessHeaders() ASVersion: 14.1 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ZPush::CommandNeedsProvisioning(9): true 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] FileStateMachine->GetState() read '912' bytes from file: '/var/lib/z-push/g/y/appldmplk0dbf4yg-devicedata' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ASDevice data loaded for user: 'ablanco' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] TopCollector(): Initialized mutexid Resource id #57 and memid Resource id #58. 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] LoopDetection(): Initialized mutexid Resource id #62 and memid Resource id #63. 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ZPush::HierarchyCommand(9): true 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] DeviceManager->ProvisioningRequired('713581845') saved device key '713581845': false 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] DeviceManager->getPolicyName(): determined policy name: 'default' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ZPush::CommandNeedsAuthentication(9): true 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] KopanoBackend->Logon(): Trying to authenticate user 'ablanco'.. 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] KopanoBackend->openMessageStore('ablanco'): Found 'DEFAULT' store: 'Resource id #78' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] KopanoBackend->Logon(): User 'ablanco' is authenticated 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] Store supports properties containing Unicode characters. 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ZPush::CommandNeedsPlainInput(9): false 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] I <FolderHierarchy:FolderSync> 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] I <FolderHierarchy:SyncKey> 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] I {ef18fb64-7ad4-4179-b73f-8b44d40d2421}2 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] I </FolderHierarchy:SyncKey> 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] StateManager->loadHierarchyCache(): 'appldmplk0dbf4yg-ef18fb64-7ad4-4179-b73f-8b44d40d2421-hc-2' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] StateManager::UnLinkState(''): saved state 'ef18fb64-7ad4-4179-b73f-8b44d40d2421' will be deleted. 29/04/2018 12:12:10 [15510] [ INFO] [ablanco] StateNotFoundException: No hierarchy UUID linked to device. Requesting folder resync. - code: 0 - file: /usr/share/z-pu sh/lib/core/statemanager.php:486 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] I </FolderHierarchy:FolderSync> 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 9 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] O <FolderHierarchy:FolderSync> 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] O <FolderHierarchy:Status> 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] O 9 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] O </FolderHierarchy:Status> 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] O </FolderHierarchy:FolderSync> 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] WBXMLEncoder->endTag() WBXML output completed 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] WBXML-OUT: AwFqAAAHVkwDOQABAQ== 29/04/2018 12:12:10 [15510] [WBXML] [ablanco] WBXML-IN : AwFqAAAHVlIDe2VmMThmYjY0LTdhZDQtNDE3OS1iNzNmLThiNDRkNDBkMjQyMX0yAAEB 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] LoopDetection->ProcessLoopDetectionTerminate() 29/04/2018 12:12:10 [15510] [ INFO] [ablanco] cmd='FolderSync' memory='5.82 MiB/6.25 MiB' time='0.06s' devType='iPad' devId='XXXX' getUser='ablanco' from='77.228.72.112' idle='0s' version='2.4.1.beta1+3-0' method='POST' httpcode='200' 29/04/2018 12:12:10 [15510] [DEBUG] [ablanco] -------- End 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] -------- Start 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] cmd='' devType='' devId='' getUser='ablanco' from='77.228.72.112' version='2.4.1.beta1+3-0' method='OPTIONS' 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] Used timezone 'Europe/Madrid' 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] BackendKopano using PHP-MAPI version: 8.6.80 - PHP version: 5.5.9-1ubuntu4.24 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] Request::ProcessHeaders() ASVersion: 14.1 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] KopanoBackend->Logon(): Trying to authenticate user 'ablanco'.. 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] KopanoBackend->openMessageStore('ablanco'): Found 'DEFAULT' store: 'Resource id #49' 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] KopanoBackend->Logon(): User 'ablanco' is authenticated 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] Store supports properties containing Unicode characters. 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,Delete Collection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search ,Ping,Notify,ItemOperations,Settings 29/04/2018 12:13:08 [23261] [ INFO] [ablanco] Options request 29/04/2018 12:13:08 [23261] [ INFO] [ablanco] cmd='' memory='3.58 MiB/4.25 MiB' time='0.05s' devType='' devId='' getUser='ablanco' from='77.228.72.112' idle='0s' ver sion='2.4.1.beta1+3-0' method='OPTIONS' httpcode='200' 29/04/2018 12:13:08 [23261] [DEBUG] [ablanco] -------- End
Arturo