Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

    [FATAL] [pieter] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command

    Z-Push when using Kopano
    2
    15
    1978
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • Manfred
      Manfred Kopano @pwhooftman last edited by

      Hi @pwhooftman,

      please enable WBXML level logging for the user pieter and post the log here.

      Manfred

      pwhooftman 1 Reply Last reply Reply Quote 0
      • pwhooftman
        pwhooftman @Manfred last edited by pwhooftman

        @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
        1 Reply Last reply Reply Quote 0
        • pwhooftman
          pwhooftman last edited by pwhooftman

          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
          1 Reply Last reply Reply Quote 0
          • pwhooftman
            pwhooftman last edited by

            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.

            1 Reply Last reply Reply Quote 0
            • Manfred
              Manfred Kopano last edited by

              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

              1 Reply Last reply Reply Quote 0
              • pwhooftman
                pwhooftman last edited by

                Yes, i already tried with another mobile, even with a different android version, and with different user accounts, same problems.

                1 Reply Last reply Reply Quote 0
                • Manfred
                  Manfred Kopano last edited by

                  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

                  pwhooftman 1 Reply Last reply Reply Quote 0
                  • pwhooftman
                    pwhooftman @Manfred last edited by

                    @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.cfg

                    The 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 Reply Last reply Reply Quote 0
                    • pwhooftman
                      pwhooftman last edited by pwhooftman

                      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…

                      1 Reply Last reply Reply Quote 0
                      • pwhooftman
                        pwhooftman last edited by

                        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:230

                        So, 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…

                        1 Reply Last reply Reply Quote 0
                        • pwhooftman
                          pwhooftman last edited by

                          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.

                          1 Reply Last reply Reply Quote 0
                          • pwhooftman
                            pwhooftman last edited by

                            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.

                            1 Reply Last reply Reply Quote 0
                            • First post
                              Last post