[FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command
-
Running Kopano4s on my Synology DS918+ since a few days. I migrated from an Univention UCS Virtual machine with Kopano running on my DS918+ also.
On my LGV30 Android phone, i have set up an account in VMWare Boxer email for user ‘Infohc’, this user has a 2.6 Gb store. Everything syncs fine.
I want to setup another account for user pieter which has a 2.4Gb store. I enter exactly the same server credentials, but the message ‘Account configuration not possible. Connection to the server not possible’ arises immediately. If i try other email clients, the attempt to make a connection lasts forever.Z-push.log shows:
devId='boxerc9a475eec6124a2c5' getUser='infohc' from='10.0.0.138' idle='91s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 09:59:50 [19096] [ INFO] [info] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 600 seconds) 20/04/2020 09:59:54 [19097] [ INFO] [pieter] Options request 20/04/2020 09:59:54 [19097] [ INFO] [pieter] cmd='' memory='1.59 MiB/2.00 MiB' time='0.02s' devType='' devId='' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='OPTIONS' httpcode='200' 20/04/2020 09:59:54 [19098] [ INFO] [pieter] ProvisioningRequiredException: Retry after sending a PROVISION command - code: 0 - file: /usr/share/z-push/index.php:82 20/04/2020 09:59:54 [19098] [ INFO] [pieter] User-agent: 'AirWatch Boxer (LG-H930; Android 9) Version 5.10.0.1/1112' 20/04/2020 09:59:54 [19098] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:59:54 [19098] [ INFO] [pieter] cmd='FolderSync' memory='1.60 MiB/2.00 MiB' time='0.00s' devType='Android' devId='boxerc9a475eec6124a2c5' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='449'As can be seen, the connection is rejected within a second. What’s the cause?
I tried removing the device from z-push, and ‘fixstates’. This behaviour occurred also irregulary when i was using the UCS Univention virtual machine. Sometimes the cnnection could be made a few hours later, and generally kept functioning once the account setup was finished.
The user ‘pieter’ syncs fine to two instances of Outlook 2016 running in my home.
Any advise is welcome.
NB. my z-push-error.log:
20/04/2020 09:11:17 [22762] [FATAL] [#unknown] Exception: (AuthenticationRequiredException) - Access denied. Please send authorisation information 20/04/2020 09:11:17 [22762] [WARN] [#unknown] IP: 10.0.0.138 failed to authenticate user 'unknown' 20/04/2020 09:11:18 [23737] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:13:17 [ 463] [FATAL] [infohc] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:14:26 [ 936] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:48:39 [25022] [WARN] [#unknown] ZPushAdmin::FixStatesHierarchyFolderData(): device 73ffb88185744f8d893d9fa5422b34dd user 'pieter' has no hierarchy synchronized! Ignoring. 20/04/2020 09:48:39 [25022] [WARN] [#unknown] ZPushAdmin::FixStatesHierarchyFolderData(): device c8134668597849e6a57e9000240343d5 user 'pieter' has no hierarchy synchronized! Ignoring. 20/04/2020 09:48:39 [25022] [WARN] [#unknown] ZPushAdmin::FixStatesHierarchyFolderData(): device ddc65f682cce47539c84a83a42dc5ef2 user 'lisa' has no hierarchy synchronized! Ignoring. 20/04/2020 09:48:39 [25022] [WARN] [#unknown] ZPushAdmin::FixStatesHierarchyFolderData(): device lgmcllsb68ohvo70 user 'pieter' has no hierarchy synchronized! Ignoring. 20/04/2020 09:49:03 [19096] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:56:32 [16964] [FATAL] [infohc] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 09:59:54 [19098] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 10:01:28 [16965] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 20/04/2020 10:07:42 [20321] [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command -
Hi @pwhooftman,
it looks like that the device doesn’t send the provisioning information for the second account. Did you try to reboot it?
Did you try to configure both accounts using the default Android client instead of VMWare Boxer?
Manfred
-
Thanks for your response,
- i tried rebooting
- i tried setting up the account via the standard Android accounts (type ‘Microsoft Exchange’): the messages on the phone states ‘connecting to server’ endlessly, while z-push-error.log fills up with:
20/04/2020 15:58:20 [12029] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:20 [11967] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:21 [10724] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:21 [12927] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:21 [12068] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:21 [11973] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:21 [10911] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [10723] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [12910] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [12961] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [12916] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [12959] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:22 [12922] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:23 [ 7797] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.02s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:23 [12012] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.03s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 15:58:23 [12928] [ INFO] [pieter] cmd='Provision' memory='1.89 MiB/2.00 MiB' time='0.04s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' -
Hi @pwhooftman,
please enable WBXML level logging for the user pieter and post the log here.
Manfred
-
@Manfred
Great! I let account setup on my android phone run for about 30 seconds in attempting to connect to the server. The part with timestamp 22:27:19 wa sgenerated by the email client which keeps trying to connect and repeats 20-30 times in the log file. The last 22:30:56 part was generated by the email boxer client which gives tghe message that it could not connect to the server. The boxer email client doenst keep trying so that part is logged once.Pieter.log:
20/04/2020 22:27:19 [ 1343] [DEBUG] -------- Start 20/04/2020 22:27:19 [ 1343] [DEBUG] cmd='' devType='' devId='' getUser='pieter' from='10.0.0.138' version='2.5.2+0-0' method='OPTIONS' 20/04/2020 22:27:19 [ 1343] [DEBUG] Used timezone 'Europe/Berlin' 20/04/2020 22:27:19 [ 1343] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 20/04/2020 22:27:19 [ 1343] [DEBUG] BackendKopano using PHP-MAPI version: 10.0.3 - PHP version: 7.3.14-1~deb10u1 20/04/2020 22:27:19 [ 1343] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 20/04/2020 22:27:19 [ 1343] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'pieter'.. 20/04/2020 22:27:19 [ 1343] [DEBUG] KopanoBackend->openMessageStore('pieter'): Found 'DEFAULT' store: 'Resource id #10' 20/04/2020 22:27:19 [ 1343] [DEBUG] KopanoBackend->Logon(): User 'pieter' is authenticated 20/04/2020 22:27:19 [ 1343] [DEBUG] Store supports properties containing Unicode characters. 20/04/2020 22:27:19 [ 1343] [DEBUG] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 20/04/2020 22:27:19 [ 1343] [DEBUG] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1 20/04/2020 22:27:19 [ 1343] [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 20/04/2020 22:27:19 [ 1343] [ INFO] Options request 20/04/2020 22:27:19 [ 1343] [ INFO] cmd='' memory='1.59 MiB/2.00 MiB' time='0.02s' devType='' devId='' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='OPTIONS' httpcode='200' 20/04/2020 22:27:19 [ 1343] [DEBUG] -------- End 20/04/2020 22:27:19 [ 1404] [DEBUG] -------- Start 20/04/2020 22:27:19 [ 1404] [DEBUG] cmd='' devType='' devId='' getUser='pieter' from='10.0.0.138' version='2.5.2+0-0' method='OPTIONS' 20/04/2020 22:27:19 [ 1404] [DEBUG] Used timezone 'Europe/Berlin' 20/04/2020 22:27:19 [ 1404] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 20/04/2020 22:27:19 [ 1404] [DEBUG] BackendKopano using PHP-MAPI version: 10.0.3 - PHP version: 7.3.14-1~deb10u1 20/04/2020 22:27:19 [ 1404] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 20/04/2020 22:27:19 [ 1404] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'pieter'.. 20/04/2020 22:27:19 [ 1404] [DEBUG] KopanoBackend->openMessageStore('pieter'): Found 'DEFAULT' store: 'Resource id #10' 20/04/2020 22:27:19 [ 1404] [DEBUG] KopanoBackend->Logon(): User 'pieter' is authenticated 20/04/2020 22:27:19 [ 1404] [DEBUG] Store supports properties containing Unicode characters. 20/04/2020 22:27:19 [ 1404] [DEBUG] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 20/04/2020 22:27:19 [ 1404] [DEBUG] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1 20/04/2020 22:27:19 [ 1404] [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 20/04/2020 22:27:19 [ 1404] [ INFO] Options request 20/04/2020 22:27:19 [ 1404] [ INFO] cmd='' memory='1.59 MiB/2.00 MiB' time='0.02s' devType='' devId='' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='OPTIONS' httpcode='200' 20/04/2020 22:27:19 [ 1404] [DEBUG] -------- End 20/04/2020 22:30:56 [22451] [DEBUG] -------- Start 20/04/2020 22:30:56 [22451] [DEBUG] cmd='' devType='' devId='' getUser='pieter' from='10.0.0.138' version='2.5.2+0-0' method='OPTIONS' 20/04/2020 22:30:56 [22451] [DEBUG] Used timezone 'Europe/Berlin' 20/04/2020 22:30:56 [22451] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 20/04/2020 22:30:56 [22451] [DEBUG] BackendKopano using PHP-MAPI version: 10.0.3 - PHP version: 7.3.14-1~deb10u1 20/04/2020 22:30:56 [22451] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 20/04/2020 22:30:56 [22451] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'pieter'.. 20/04/2020 22:30:56 [22451] [DEBUG] KopanoBackend->openMessageStore('pieter'): Found 'DEFAULT' store: 'Resource id #10' 20/04/2020 22:30:56 [22451] [DEBUG] KopanoBackend->Logon(): User 'pieter' is authenticated 20/04/2020 22:30:56 [22451] [DEBUG] Store supports properties containing Unicode characters. 20/04/2020 22:30:56 [22451] [DEBUG] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 20/04/2020 22:30:56 [22451] [DEBUG] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0,14.1 20/04/2020 22:30:56 [22451] [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 20/04/2020 22:30:56 [22451] [ INFO] Options request 20/04/2020 22:30:56 [22451] [ INFO] cmd='' memory='1.59 MiB/2.00 MiB' time='0.02s' devType='' devId='' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='OPTIONS' httpcode='200' 20/04/2020 22:30:56 [22451] [DEBUG] -------- End -
pieter-lgmcllsb68ohvo70.log: the following sections keep repeating over and over again
I deleted the still function account ‘infohc’ from my mobile also, and that account cannot be re-setup also.
20/04/2020 22:27:20 [ 2337] [DEBUG] -------- Start 20/04/2020 22:27:20 [ 2337] [DEBUG] cmd='Provision' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' version='2.5.2+0-0' method='POST' 20/04/2020 22:27:20 [ 2337] [DEBUG] Used timezone 'Europe/Berlin' 20/04/2020 22:27:20 [ 2337] [DEBUG] ZPush::GetBackend(): trying autoload backend 'BackendKopano' 20/04/2020 22:27:20 [ 2337] [DEBUG] BackendKopano using PHP-MAPI version: 10.0.3 - PHP version: 7.3.14-1~deb10u1 20/04/2020 22:27:20 [ 2337] [DEBUG] Request::ProcessHeaders() ASVersion: 14.1 20/04/2020 22:27:20 [ 2337] [DEBUG] ZPush::CommandNeedsProvisioning(20): false 20/04/2020 22:27:20 [ 2337] [DEBUG] ZPush::CommandNeedsAuthentication(20): false 20/04/2020 22:27:20 [ 2337] [DEBUG] FileStateMachine->GetState() read '2381' bytes from file: '/var/lib/z-push/0/7/lgmcllsb68ohvo70-devicedata' 20/04/2020 22:27:20 [ 2337] [DEBUG] ASDevice data loaded for user: 'pieter' 20/04/2020 22:27:20 [ 2337] [DEBUG] InterProcessData:__construct type: 'lgmcllsb68ohvo70' 20/04/2020 22:27:20 [ 2337] [DEBUG] TopCollector(): Initialized mutexid Resource id #9 and memid Resource id #10. 20/04/2020 22:27:20 [ 2337] [DEBUG] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 20/04/2020 22:27:20 [ 2337] [DEBUG] InterProcessData:__construct type: 'lgmcllsb68ohvo70' 20/04/2020 22:27:20 [ 2337] [DEBUG] LoopDetection(): Initialized mutexid Resource id #11 and memid Resource id #12. 20/04/2020 22:27:20 [ 2337] [DEBUG] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 20/04/2020 22:27:20 [ 2337] [DEBUG] ZPush::HierarchyCommand(20): false 20/04/2020 22:27:20 [ 2337] [DEBUG] ZPush::CommandNeedsPlainInput(20): false 20/04/2020 22:27:20 [ 2337] [DEBUG] RequestProcessor::HandleProvision(): Forcing delayed Authentication 20/04/2020 22:27:20 [ 2337] [DEBUG] KopanoBackend->Logon(): Trying to authenticate user 'pieter'.. 20/04/2020 22:27:20 [ 2337] [DEBUG] KopanoBackend->openMessageStore('pieter'): Found 'DEFAULT' store: 'Resource id #15' 20/04/2020 22:27:20 [ 2337] [DEBUG] KopanoBackend->Logon(): User 'pieter' is authenticated 20/04/2020 22:27:20 [ 2337] [DEBUG] Store supports properties containing Unicode characters. 20/04/2020 22:27:20 [ 2337] [WBXML] I <Provision:Provision> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:DeviceInformation> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:Set> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:Model> 20/04/2020 22:27:20 [ 2337] [WBXML] I LG-H930 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:Model> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:IMEI> 20/04/2020 22:27:20 [ 2337] [WBXML] I 359923080235120 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:IMEI> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:FriendlyName> 20/04/2020 22:27:20 [ 2337] [WBXML] I LG-H930 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:FriendlyName> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:OS> 20/04/2020 22:27:20 [ 2337] [WBXML] I Android9 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:OS> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:OSLanguage> 20/04/2020 22:27:20 [ 2337] [WBXML] I nl 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:OSLanguage> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:PhoneNumber> 20/04/2020 22:27:20 [ 2337] [WBXML] I 821000000000 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:PhoneNumber> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:MobileOperator> 20/04/2020 22:27:20 [ 2337] [WBXML] I OPEN 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:MobileOperator> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:UserAgent> 20/04/2020 22:27:20 [ 2337] [WBXML] I Android-LG-H930/8.0.8 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:UserAgent> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Settings:EnableOutboundSMS> 20/04/2020 22:27:20 [ 2337] [WBXML] I 0 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:EnableOutboundSMS> 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:Set> 20/04/2020 22:27:20 [ 2337] [DEBUG] Saving submitted device information 20/04/2020 22:27:20 [ 2337] [WBXML] I </Settings:DeviceInformation> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Provision:Policies> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Provision:Policy> 20/04/2020 22:27:20 [ 2337] [WBXML] I <Provision:PolicyType> 20/04/2020 22:27:20 [ 2337] [WBXML] I MS-EAS-Provisioning-WBXML 20/04/2020 22:27:20 [ 2337] [WBXML] I </Provision:PolicyType> 20/04/2020 22:27:20 [ 2337] [WBXML] I </Provision:Policy> 20/04/2020 22:27:20 [ 2337] [WBXML] I </Provision:Policies> 20/04/2020 22:27:20 [ 2337] [WBXML] I </Provision:Provision> 20/04/2020 22:27:20 [ 2337] [DEBUG] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Provision> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Settings:DeviceInformation> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Settings:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Settings:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Settings:DeviceInformation> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Policies> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Policy> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:PolicyType> 20/04/2020 22:27:20 [ 2337] [WBXML] O MS-EAS-Provisioning-WBXML 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:PolicyType> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Status> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:PolicyKey> 20/04/2020 22:27:20 [ 2337] [WBXML] O 790439685 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:PolicyKey> 20/04/2020 22:27:20 [ 2337] [DEBUG] DeviceManager->getPolicyName(): determined policy name: 'default' 20/04/2020 22:27:20 [ 2337] [DEBUG] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'devpwenabled' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'alphanumpwreq' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'devencenabled' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'docbrowseenabled' enforced with: empty (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'attenabled' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'mindevpwlenngth' enforced with: 4 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxinacttimedevlock' enforced with: 900 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxdevpwfailedattempts' enforced with: 8 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxattsize' enforced with: empty (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowsimpledevpw' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'devpwexpiration' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'devpwhistory' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowstoragecard' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowcam' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqdevenc' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowunsignedapps' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'mindevcomplexchars' enforced with: 3 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowwifi' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowtextmessaging' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowpopimapemail' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowbluetooth' enforced with: 2 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowirda' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqmansyncroam' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxcalagefilter' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowhtmlemail' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxemailagefilter' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxemailbodytruncsize' enforced with: -1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'maxemailhtmlbodytruncsize' enforced with: -1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqsignedsmimemessages' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqencsmimemessages' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqsignedsmimealgorithm' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'reqencsmimealgorithm' enforced with: 0 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowsmimeencalgneg' enforced with: 2 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowsmimesoftcerts' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowbrowser' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowconsumeremail' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [WBXML] Policy 'allowinternetsharing' enforced with: 1 (string) 20/04/2020 22:27:20 [ 2337] [DEBUG] DeviceManager->SavePolicyHashAndName(): Set policy: default with hash: 794e30742dfdda378caebc4203d4c843 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:Data> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:EASProvisionDoc> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:DevicePasswordEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:DevicePasswordEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AlphanumericDevicePasswordRequired> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AlphanumericDevicePasswordRequired> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:PasswordRecoveryEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:PasswordRecoveryEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:DeviceEncryptionEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:DeviceEncryptionEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AttachmentsEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AttachmentsEnabled> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MinDevicePasswordLength> 20/04/2020 22:27:20 [ 2337] [WBXML] O 4 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MinDevicePasswordLength> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxInactivityTimeDeviceLock> 20/04/2020 22:27:20 [ 2337] [WBXML] O 900 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxInactivityTimeDeviceLock> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxDevicePasswordFailedAttempts> 20/04/2020 22:27:20 [ 2337] [WBXML] O 8 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxDevicePasswordFailedAttempts> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxAttachmentSize/> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowSimpleDevicePassword> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowSimpleDevicePassword> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:DevicePasswordExpiration> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:DevicePasswordExpiration> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:DevicePasswordHistory> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:DevicePasswordHistory> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowStorageCard> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowStorageCard> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowCamera> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowCamera> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireDeviceEncryption> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireDeviceEncryption> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowUnsignedApplications> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowUnsignedApplications> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowUnsignedInstallationPackages> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowUnsignedInstallationPackages> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MinDevicePasswordComplexCharacters> 20/04/2020 22:27:20 [ 2337] [WBXML] O 3 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MinDevicePasswordComplexCharacters> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowWiFi> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowWiFi> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowTextMessaging> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowTextMessaging> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowPOPIMAPEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowPOPIMAPEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowBluetooth> 20/04/2020 22:27:20 [ 2337] [WBXML] O 2 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowBluetooth> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowIrDA> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowIrDA> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireManualSyncWhenRoaming> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireManualSyncWhenRoaming> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowDesktopSync> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowDesktopSync> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxCalendarAgeFilter> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxCalendarAgeFilter> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowHTMLEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowHTMLEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxEmailAgeFilter> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxEmailAgeFilter> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxEmailBodyTruncationSize> 20/04/2020 22:27:20 [ 2337] [WBXML] O -1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxEmailBodyTruncationSize> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:MaxEmailHTMLBodyTruncationSize> 20/04/2020 22:27:20 [ 2337] [WBXML] O -1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:MaxEmailHTMLBodyTruncationSize> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireSignedSMIMEMessages> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireSignedSMIMEMessages> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireEncryptedSMIMEMessages> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireEncryptedSMIMEMessages> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireSignedSMIMEAlgorithm> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireSignedSMIMEAlgorithm> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:RequireEncryptionSMIMEAlgorithm> 20/04/2020 22:27:20 [ 2337] [WBXML] O 0 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:RequireEncryptionSMIMEAlgorithm> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowSMIMEEncryptionAlgorithmNegotiation> 20/04/2020 22:27:20 [ 2337] [WBXML] O 2 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowSMIMEEncryptionAlgorithmNegotiation> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowSMIMESoftCerts> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowSMIMESoftCerts> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowBrowser> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowBrowser> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowConsumerEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowConsumerEmail> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowRemoteDesktop> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowRemoteDesktop> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:AllowInternetSharing> 20/04/2020 22:27:20 [ 2337] [WBXML] O 1 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:AllowInternetSharing> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:UnapprovedInROMApplicationList/> 20/04/2020 22:27:20 [ 2337] [WBXML] O <Provision:ApprovedApplicationList/> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:EASProvisionDoc> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Data> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Policy> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Policies> 20/04/2020 22:27:20 [ 2337] [WBXML] O </Provision:Provision> 20/04/2020 22:27:20 [ 2337] [DEBUG] WBXMLEncoder->endTag() WBXML output completed 20/04/2020 22:27:20 [ 2337] [WBXML] WBXML-OUT: AwFqAAAORUsDMQABABJWRgMxAAEBAA5GR0gDTVMtRUFTLVByb3Zpc2lvbmluZy1XQlhNTAABSwMxAAFJAzc5MDQzOTY4NQABSk1OAzAAAU8DMAABUQMwAAFQAzAAAVMDMQABVAM0AAFVAzkwMAABVgM4AAEXWAMxAAFZAzAAAVoDMAABWwMxAAFcAzEAAV0DMAABXgMxAAFfAzEAAWADMwABYQMxAAFiAzEAAWMDMQABZAMyAAFlAzEAAWYDMAABZwMxAAFoAzAAAWkDMQABagMwAAFrAy0xAAFsAy0xAAFtAzAAAW4DMAABbwMwAAFwAzAAAXEDMgABcgMxAAFzAzEAAXQDMQABdQMxAAF2AzEAATc5AQEBAQE= 20/04/2020 22:27:20 [ 2337] [WBXML] WBXML-IN : AwFqAAAORQASVkhXA0xHLUg5MzAAAVgDMzU5OTIzMDgwMjM1MTIwAAFZA0xHLUg5MzAAAVoDQW5kcm9pZDkAAVsDbmwAAVwDODIxMDAwMDAwMDAwAAFiA09QRU4AAWADQW5kcm9pZC1MRy1IOTMwLzguMC44AAFhAzAAAQEBAA5GR0gDTVMtRUFTLVByb3Zpc2lvbmluZy1XQlhNTAABAQEB 20/04/2020 22:27:20 [ 2337] [DEBUG] LoopDetection->ProcessLoopDetectionTerminate() 20/04/2020 22:27:20 [ 2337] [ INFO] cmd='Provision' memory='1.86 MiB/2.00 MiB' time='0.04s' devType='LGPhone' devId='lgmcllsb68ohvo70' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 20/04/2020 22:27:20 [ 2337] [DEBUG] -------- End -
I’m curious if anybody can show some light on this matter. Some additional info:
- the problem is not user related: attempts to set up other user accounts on the same phone leads to the same errors
- the problem is not limited to the specific phone: when attempting to set up an account on an older mobile, i managed to get past the connecting to the server phase, but afterwards the emailprogram tried to fetch the emails for ever and teh log was filling up with these entries:
22/04/2020 22:13:03 [18178] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 22/04/2020 22:13:06 [17781] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 22/04/2020 22:13:06 [17781] [WARN] [pieter] SyncCollections->CountChange(): exporter can not be re-configured due to state error, emulating change in folder to force Sync. 22/04/2020 22:13:07 [19916] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 22/04/2020 22:13:09 [19422] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230- two different pc’s with outlook 2016 sync several emailboxes via Z-push just fine.
After extensive googling, i’m starting to think it’s related to MariaDB10, thinking that my setting up was plagued with connection problems to the database also. Wil try a Mysql server in docker next.
-
Hi @pwhooftman,
the logs look ok for me, but your mobile seems not be able to process the responses. Maybe you could debug it with adb to find out what’s going on.
Do you have another mobile device to connect with those accounts?
Manfred
-
Yes, i already tried with another mobile, even with a different android version, and with different user accounts, same problems.
-
Hi @pwhooftman,
the exporter errors indicate an issue with the KC (or maybe with the user’s store only).
Did you try to create a new account and sync it on a mobile?
Manfred
-
Thanks for all your efforts!
A new user with 1 message syncs fine!
For test purposes, i have set define(‘PROVISIONING’, false);
in /etc/z-push/z-push.conf.php
and
enable_enhanced_ics = no in server.cfgThe setup of the account pieter then completes on the mobile, but synchronizing stays stuck on ’ 0 of 15586 messages are being synchronized’ while z-push.log fills with:
23/04/2020 23:04:54 [ 132] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 23/04/2020 23:04:54 [ 132] [ INFO] [pieter] cmd='Sync' memory='2.03 MiB/2.00 MiB' time='0.07s' devType='Android' devId='boxerc4e9a9b90eef1207e' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 23/04/2020 23:04:54 [ 140] [ INFO] [pieter] cmd='Sync' memory='2.00 MiB/2.00 MiB' time='0.20s' devType='Android' devId='boxerc4e9a9b90eef1207e' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 23/04/2020 23:04:54 [ 150] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 23/04/2020 23:04:54 [ 150] [ INFO] [pieter] cmd='Sync' memory='2.03 MiB/4.00 MiB' time='0.06s' devType='Android' devId='boxerc4e9a9b90eef1207e' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200' 23/04/2020 23:04:55 [ 133] [ INFO] [pieter] cmd='Sync' memory='2.00 MiB/2.00 MiB' time='0.22s' devType='Android' devId='boxerc4e9a9b90eef1207e' getUser='pieter' from='10.0.0.138' idle='0s' version='2.5.2+0-0' method='POST' httpcode='200'So obviouslyly this is related to the user pieter or his big mailbox. Whats the next step? i already tried deleting all devices on which pieter was synchronized via z-push-admin
For your information: de mailbox pieter was kopano-backupped from a UCS Invention Kopano server.
-
1 I started fresh
- Removed account pieter from mobile
- Removed account pieter from Outlook 2016
- I left ‘define(‘Provisioning’, false) in z-push-config.php for the moment
- Commented out enable_enhanced_ics = no in server.cfg
- Mysql settings in server.cfg:
o Host : localhost (with setting ‘localhost’, the socket is used)
o Port: 3307
o User: kopano
o Password: the pw generated by Kopano - Z-push-admin -a remove -u pieter
- Delete user pieter via kopano4s gui
- Create user pieter via kopano4s gui
- Login with Webapp: ok
- Sent 1 message: ok
2 Set up account on mobile:
- Added account for pieter
- 1 sent message synced ok from server to mobile
- Delete 1 message on mobile: synced back to server ok
3 Restore pieter store
- Kopano-backup –restore -u pieter -l DEBUG
- Store grows to 2470MB
4 Synchronization complete
- Emails flow into the mobile while the restore progresses, extra folders in Postvak IN are created and filled while syncing
- All +15000 messages succesfully synced while restoring
- Mobile stays synced succesfully for 2 hours, via wifi and 4G
- Z-push logs show no warnings or fatals, only infos
- Changes on the phone and on the server are synced correctly
5 Removed account pieter from mobile
6 Readded account pieter to mobile
- Syncing still works
- Z-push logs show no warnings or fatals, only infos
So far so good. Conclusion: when setting up a user, first setup syncing to my phone, then start restoring the backup.
Now here comes the 1 phenomona i cant explain:
- previously i performed exactly the same 6 steps as above, but with a tcp port connection to MariaDB (created a kopano2@% user, and set mysql host= 10.0.0180).
- then i added my next user ‘infohc’ as an account to my mobile.
- z-push.log started filling with warnings for infohc “StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230” which is to be expected: appearantly i have to go through the same 6 steps for this account also…
- … but it also broke the syncing for user pieter, the same warnings started appearing for pieter also and syncing stopped!
I havent been able to reproduce this…
-
Well, that didnt last long.
All email from all 3 accounts where missing on my mobile this morning.
Syncing has seized.
Logs flooded with errors.26/04/2020 06:38:13 [29683] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 26/04/2020 06:38:14 [ 3922] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230 26/04/2020 06:38:16 [30112] [WARN] [pieter] StatusException: ExportChangesICS->InitializeExporter(): Error, mapi_exportchanges_config() failed: 0xFFFFFFFF8004010F - code: 12 - file: /usr/share/z-push/backend/kopano/exporter.php:230So, 3 accounts which i restored from a previous install which all three are > 2Gb is size fail syncing within a day. Only a new created account with 1 message keeps in sync.
I’m about to give up on Kopano…
-
I installed a separate mysql docker container & phpmyadmin container, restored an sqldump into the kopano database, and adjusted server.cfg accordingly.
The accounts on my phone started resyncing instantly, and some errors where logged during the resync, they disappeared after the sync had settles.I’ll update this post later, but so far he local Mariadb10 seems the cause of my problems. I have read before about problems with Mariadb10 and big stores.
-
Solved!
After switching over from the Synology package MariaDB10 to a docker container Mysql (and a Phpmyadmin container to administer the Mysql database in that container), all syncing has been flawless. Zero errors and warnings since the completion of the initial sync to my mobile and pc’s.
So all previous assumptions that the problems had to do with restoring from a previous Koppano install where false.
Also, i rule out a cause in my specific setup, because i did a complete Synology DSM re-install prior to trying to install and use Kopano4s with MariaDB10. From the very first install attempts a few months back, but also on that freshly installed DSM, i had strange errors where kopano4s could not connect to the database, or would only create like 17 out of the 29 desired tables, or the package had to be restarted twice before the docker container would not crash. In my opinion, Kopano4s and MariaDB10 is a bad combination.
