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

    Outlook mail folders are empty. NoHierarchyCacheAvailableException

    Z-Push when using other backends
    3
    8
    635
    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.
    • fkoyer
      fkoyer last edited by fkoyer

      Steps to reproduce:

      1. Create a new Outlook profile using Exchange ActiveSync
      2. Allow Outlook to fully synchronize all folders
      3. Close Outlook
      4. Re-open Outlook.

      At this point, all mail folders are there but they are all empty. Outlook is alternating between “Waiting for server response” and “All folders are up to date”.

      When I run z-push-admin -a list there are now two devices for the same user:

      All synchronized devices

Device id                           Synchronized users
-----------------------------------------------------
2bedddf60bc34174bb6c974920c27e8c    xxxxx@xxxxxxxxxx
ed71fdf520e3473b9d92bd5aae96aba1    xxxxx@xxxxxxxxxx

      In the log I see lots of NoHierarchyCacheAvailableException errors

      27/12/2021 21:48:01 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Options request
27/12/2021 21:48:01 [28817] [ INFO] [xxxxx@xxxxxxxxxx] cmd='' memory='1.67 MiB/2.00 MiB' time='0.39s' devType='' devId='' getUser='xxxxx@xxxxxxxxxx' from='108.237.14.212' idle='0s' version='2.6.4+0' method='OPTIONS' httpcode='200'
27/12/2021 21:48:01 [28817] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: No hierarchy UUID linked to device. Requesting folder resync. - code: 0 - file: /usr/share/z-push/lib/core/statemanager.php:486
27/12/2021 21:48:01 [28817] [ INFO] [xxxxx@xxxxxxxxxx] LoopDetection->ProcessLoopDetectionIsHierarchyResyncRequired(): Potential loop detected. Full hierarchysync indicated.
27/12/2021 21:48:01 [28817] [ INFO] [xxxxx@xxxxxxxxxx] cmd='FolderSync' memory='1.87 MiB/4.00 MiB' time='0.48s' devType='WindowsOutlook' devId='2bedddf60bc34174bb6c974920c27e8c' getUser='xxxxx@xxxxxxxxxx' from='108.237.14.212' idle='0s' version='2.6.4+0' method='POST' httpcode='200'
27/12/2021 21:48:02 [28817] [ INFO] [xxxxx@xxxxxxxxxx] ExportChangesDiff->InitializeExporter(): Found '16' changes for 'hierarchy'
27/12/2021 21:48:03 [28817] [ INFO] [xxxxx@xxxxxxxxxx] ExportChangesDiff->InitializeExporter(): Found '2' changes for 'hierarchy'
27/12/2021 21:48:03 [28817] [ INFO] [xxxxx@xxxxxxxxxx] ExportChangesDiff->InitializeExporter(): Found '1' changes for 'hierarchy'
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] cmd='FolderSync' memory='2.35 MiB/4.00 MiB' time='2.26s' devType='WindowsOutlook' devId='2bedddf60bc34174bb6c974920c27e8c' getUser='xxxxx@xxxxxxxxxx' from='108.237.14.212' idle='0s' version='2.6.4+0' method='POST' httpcode='200'
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/ea705ceb' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:04 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/fa312f15' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:04 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'c/CMyCalendar-df7dfca6-88d3-41a4-b3f6-98ab29d16497' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:04 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:04 [28817] [ INFO] [xxxxx@xxxxxxxxxx] cmd='Sync' memory='2.13 MiB/4.00 MiB' time='0.47s' devType='WindowsOutlook' devId='2bedddf60bc34174bb6c974920c27e8c' getUser='xxxxx@xxxxxxxxxx' from='108.237.14.212' idle='0s' version='2.6.4+0' method='POST' httpcode='200'
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/d71fc435' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:05 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'd/contacts' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:05 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/167ae2d2' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:05 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/0457ecd1' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] Full device resync requested
27/12/2021 21:48:05 [28817] [WARN] [xxxxx@xxxxxxxxxx] Not possible to determine class of request. Request did not contain class and apparently there is an issue with the HierarchyCache.
27/12/2021 21:48:05 [28817] [ INFO] [xxxxx@xxxxxxxxxx] NoHierarchyCacheAvailableException: Folderid 'i/050cea65' is not fully synchronized on the device - code: 0 - file: /usr/share/z-push/lib/core/devicemanager.php:466

      Running PHP 7.4.27, Z-Push 2.6.4 on CentOS 7.9 with IMAP Backend + SQL + memcached.

      liverpoolfcfan 1 Reply Last reply Reply Quote 0
      • JungleMarc
        JungleMarc last edited by

        @fkoyer said in Outlook mail folders are empty. NoHierarchyCacheAvailableException:

        ierarchyCache

        Bit of a long shot here, and maybe this is not related at all but:

        Do you have php-curl installed, if yes which version?

        And is curl enabled in your phpenmod?

        Merry Xmas and happy new year, keep in touch

        Marc

        fkoyer 1 Reply Last reply Reply Quote 0
        • fkoyer
          fkoyer @JungleMarc last edited by

          Hi @junglemarc,

          Merry Christmas to you too. I do have php-curl installed. I don’t know what phpenmod is. That could be an Ubuntu thing and I’m on CentOS. Here is the output from php -i

          curl

cURL support => enabled
cURL Information => 7.29.0
Age => 3
Features
AsynchDNS => Yes
CharConv => No
Debug => No
GSS-Negotiate => Yes
IDN => Yes
IPv6 => Yes
krb4 => No
Largefile => Yes
libz => Yes
NTLM => Yes
NTLMWB => Yes
SPNEGO => No
SSL => Yes
SSPI => No
TLS-SRP => No
Protocols => dict, file, ftp, ftps, gopher, http, https, imap, imaps, ldap, ldaps, pop3, pop3s, rtsp, scp, sftp, smtp, smtps, telnet, tftp
Host => x86_64-redhat-linux-gnu
SSL Version => NSS/3.53.1
ZLib Version => 1.2.7
libSSH Version => libssh2/1.8.0

Directive => Local Value => Master Value
curl.cainfo => no value => no value

          Any other thoughts? It seems that the problem is with the state information. For some reason it is creating a new device id instead of using the existing one. I tried switching back to the FILE state machine but the same thing happens. The only difference is the SQL events in the log are replaced by something like this:

          28/12/2021 19:46:52 [ 1001] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: FileStateMachine->GetStateHash(): Could not locate state '/var/lib/z-push/0/b/d5b3a6c093be401d917af5c3419024b0-devicedata' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:93
28/12/2021 19:46:52 [ 1001] [ INFO] [xxxxx@xxxxxxxxxx] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/0/b/d5b3a6c093be401d917af5c3419024b0-bs-1640720812' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:124

          I’ve checked that /var/lib/z-push/0/b/d5b3a6c093be401d917af5c3419024b0-devicedata exists and is writeable by the web server:

          -rw-r--r-- 1 apache apache 606 Dec 28 19:39 /var/lib/z-push/0/b/d5b3a6c093be401d917af5c3419024b0-devicedata

          However, it’s using the wrong device id. d5b3a6c093be401d917af5c3419024b0 is the empty one. It should be 10182b8f032044ddb256fd897d9682e2 as that’s the one that it originally sync’ed with. So it goes back to why is it creating a new device id when I close and re-open Outlook?

          Thanks and Happy New Year
          Kent

          1 Reply Last reply Reply Quote 0
          • liverpoolfcfan
            liverpoolfcfan @fkoyer last edited by liverpoolfcfan

            @fkoyer Do you have Selinux enabled by any chance?
            And, if so, have you set the appropriate profiles on the z-push data folders?

            run the command

            # getenforce

            If it returns Enforcing - then selinux is enabled and protecting your system

            Try setting it to Permissive mode to see if sync works, and if it does you have identified your problem.

            # setenforce 0

            will set it to Permissive mode. This will allow file IO/other interactions it would otherwise block.

            If sync works, then read up on the selinux permissions you need and set them appropriatel, and turn enforcing back on.

            # setenforce 1

            will turn it back on again.

            fkoyer 1 Reply Last reply Reply Quote 0
            • fkoyer
              fkoyer @liverpoolfcfan last edited by

              Hi @liverpoolfcfan

              selinux is set to disabled

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

                By the way, I would always suggest you set Outlook to sync 1 month of data first, and allow everything to sync completely - contacts/calendar/tasks/1 month’s emails. Only after that has completed, and settled down should you change the setting to sync all (if you require it)

                fkoyer 1 Reply Last reply Reply Quote 0
                • fkoyer
                  fkoyer @liverpoolfcfan last edited by

                  Thanks for the suggestion @liverpoolfcfan. Unfortunately this problem occurs even with small mailboxes (~7 MB)

                  fkoyer 1 Reply Last reply Reply Quote 0
                  • fkoyer
                    fkoyer @fkoyer last edited by

                    It appears the problem is with Outlook (go figure). The first time I open Outlook after creating a new profile I can see the Device ID in my Apache logs:

                    x.x.x.x - xxxxx@xxxxxxxxxx [30/Dec/2021:01:23:43 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=FolderSync&User=xxxxx@xxxxxxxxxx&DeviceId=EFB9B5DDB53843B5AA865100AA459178&DeviceType=WindowsOutlook15 HTTP/1.1" 200 498

                    However, if I close Outlook and re-open it, I see a different Device ID in my Apache logs:

                    x.x.x.x - xxxxx@xxxxxxxxxx [30/Dec/2021:01:30:18 +0000] "POST /Microsoft-Server-ActiveSync?Cmd=FolderSync&User=xxxxx@xxxxxxxxxx&DeviceId=E429C4ACF36A4108AFF029F8D3C503EF&DeviceType=WindowsOutlook15 HTTP/1.1" 200 13

                    I found that the Device ID is stored in the Windows registry at:

                    HKEY_CURRENT_USER\SOFTWARE\Microsoft\Office\16.0\Outlook\Profiles\{profile_name}\9375CFF0413111d3B88A00104B2A6676\00000002\EAS DeviceId

                    If I change the Device ID in the registry back to the original one, everything works. Has anyone else run into this?? Outlook does not save the Device ID in the registry after the initial sync. The next time I open Outlook, it creates a new Device ID and stores it in the above key. I am using Outlook Version 2111 Build 16.0.14701.20254

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