Merge pull request #399 in ZP/z-push from...

Merge pull request #399 in ZP/z-push from bugfix/ZP-1077-deleted-folder-causes-endless-loop to develop

* commit '5c505fd1':
  ZP-1077 Removed debug log.
  ZP-1077 Added ProcessLoopDetection to catch a Ping/Sync loop where sync has errors but Ping continues to trigger syncs for it; added ProcessLoopDetection for the case where Ping sees state errors for a synched folder, triggers a sync but the folder is not being synchronized. In both cases Ping will invoke a FolderSync (status 7) instead of sending fake changes. FolderSync will check the relation between the hierarchy cache and synched data information and remove states of folders that are not in the hierarchycache anymore.

src/lib/core/devicemanager.php

@@ -729,6 +729,10 @@ class DeviceManager {
     public function IsHierarchySyncRequired() {
         $this->loadDeviceData();
 
+        if ($this->loopdetection->ProcessLoopDetectionIsHierarchySyncAdvised()) {
+            return true;
+        }
+
         // if the hash of the additional folders changed, we have to sync the hierarchy
         if ($this->additionalFoldersHash != $this->getAdditionalFoldersHash()) {
             $this->hierarchySyncRequired = true;
@@ -841,6 +845,32 @@ class DeviceManager {
         return $this->loopdetection->SetSyncStateUsage($folderid, $uuid, $counter);
     }
 
+    /**
+     * Checks the data integrity of the data in the hierarchy cache and the data of the content data (synchronized folders).
+     * If a folder is deleted, the sync states could still be on the server (and being loaded by PING) while
+     * the folder is not being synchronized anymore. See also https://jira.z-hub.io/browse/ZP-1077
+     *
+     * @access public
+     * @return boolean
+     */
+    public function CheckFolderData() {
+        ZLog::Write(LOGLEVEL_DEBUG, "DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders");
+
+        $hc = $this->device->GetHierarchyCache();
+        $notInCache = array();
+        foreach ($this->device->GetAllFolderIds() as $folderid) {
+            $uuid = $this->device->GetFolderUUID($folderid);
+            if ($uuid) {
+                // has a UUID but is not in the cache?! This is deleted, remove the states.
+                if (! $hc->GetFolder($folderid)) {
+                    ZLog::Write(LOGLEVEL_WARN, sprintf("DeviceManager->CheckFolderData(): Folder '%s' has sync states but is not in the hierarchy cache. Removing states.", $folderid));
+                    StateManager::UnLinkState($this->device, $folderid);
+                }
+            }
+        }
+        return true;
+    }
+
     /**
      * Sets the current status of the folder
      *

src/lib/core/loopdetection.php

@@ -162,6 +162,7 @@ class LoopDetection extends InterProcessData {
      * @return boolean
      */
     public function ProcessLoopDetectionAddStatus($folderid, $status) {
+        ZLog::Write(LOGLEVEL_DEBUG, sprintf("LoopDetection->ProcessLoopDetectionAddStatus: '%s' with status %d", $folderid?$folderid:'hierarchy', $status));
         // generate entry if not already there
         self::GetProcessEntry();
 
@@ -192,6 +193,73 @@ class LoopDetection extends InterProcessData {
         return $this->updateProcessStack();
     }
 
+    /**
+     * Indicates if a simple Hierarchy sync should be done after Ping.
+     *
+     * When trying to sync a non existing folder, Sync will return Status 12.
+     * This should trigger a hierarchy sync by the client, but this is not always done.
+     * Clients continue trying to Ping, which fails as well and triggers a Sync again.
+     * This goes on forever, like here: https://jira.z-hub.io/browse/ZP-1077
+     *
+     * Ping could indicate to perform a FolderSync as well after a few Sync/Ping cycles.
+     *
+     * @access public
+     * @return boolean
+     *
+     */
+    public function ProcessLoopDetectionIsHierarchySyncAdvised() {
+        $me = self::GetProcessEntry();
+        if ($me['cc'] !== ZPush::COMMAND_PING) {
+            return false;
+        }
+
+        $loopingFolders = array();
+
+        $lookback = self::$start - 600; // look at the last 5 min
+        foreach ($this->getProcessStack() as $se) {
+            if ($se['time'] > $lookback && $se['time'] < (self::$start-1)) {
+                // look for sync command
+                if (isset($se['stat']) && ($se['cc'] == ZPush::COMMAND_SYNC || $se['cc'] == ZPush::COMMAND_PING)) {
+                    foreach($se['stat'] as $key => $value) {
+                        // we only care about hierarchy errors of this folder
+                        if ($se['cc'] == ZPush::COMMAND_SYNC) {
+                            if ($value == SYNC_STATUS_FOLDERHIERARCHYCHANGED) {
+                                ZLog::Write(LOGLEVEL_DEBUG, sprintf("LoopDetection->ProcessLoopDetectionIsHierarchySyncAdvised(): seen Sync command with Exception or folderid '%s' and code '%s'", $key, $value ));
+                            }
+                        }
+                        if (!isset($loopingFolders[$key])) {
+                            $loopingFolders[$key] = array(ZPush::COMMAND_SYNC => array(), ZPush::COMMAND_PING => array());
+                        }
+                        if (!isset($loopingFolders[$key][$se['cc']][$value])) {
+                            $loopingFolders[$key][$se['cc']][$value] = 0;
+                        }
+                        $loopingFolders[$key][$se['cc']][$value]++;
+                    }
+                }
+            }
+        }
+
+        $filtered = array();
+        foreach ($loopingFolders as $fid => $data) {
+            // Ping is constantly generating changes for this folder
+            if (isset($data[ZPush::COMMAND_PING][SYNC_PINGSTATUS_CHANGES]) && $data[ZPush::COMMAND_PING][SYNC_PINGSTATUS_CHANGES] >= 3) {
+                // but the Sync request is not treating it (not being requested)
+                if (count($data[ZPush::COMMAND_SYNC]) == 0) {
+                    ZLog::Write(LOGLEVEL_INFO, sprintf("LoopDetection->ProcessLoopDetectionIsHierarchySyncAdvised(): Ping loop of folderid '%s' detected that is not being synchronized.", $fid));
+                    return true;
+                }
+                // Sync is executed, but a foldersync should be executed (hierarchy errors)
+                if (isset($data[ZPush::COMMAND_SYNC][SYNC_STATUS_FOLDERHIERARCHYCHANGED]) &&
+                        $data[ZPush::COMMAND_SYNC][SYNC_STATUS_FOLDERHIERARCHYCHANGED] > 3 ) {
+                    ZLog::Write(LOGLEVEL_INFO, sprintf("LoopDetection->ProcessLoopDetectionIsHierarchySyncAdvised(): Sync(with error)/Ping loop of folderid '%s' detected.", $fid));
+                    return true;
+                }
+            }
+        }
+
+        return false;
+    }
+
     /**
      * Indicates if a full Hierarchy Resync is necessary
      *
@@ -220,6 +288,11 @@ class LoopDetection extends InterProcessData {
                 // look for sync command
                 if (isset($se['stat']) && ($se['cc'] == ZPush::COMMAND_SYNC || $se['cc'] == ZPush::COMMAND_PING)) {
                     foreach($se['stat'] as $key => $value) {
+                        // don't count PING with changes on a folder or sync with success
+                        if (($se['cc'] == ZPush::COMMAND_PING && $value == SYNC_PINGSTATUS_CHANGES) ||
+                            ($se['cc'] == ZPush::COMMAND_SYNC && $value == SYNC_STATUS_SUCCESS) ) {
+                            continue;
+                        }
                         if (!isset($seenFailed[$key]))
                             $seenFailed[$key] = 0;
                         $seenFailed[$key]++;

src/lib/request/foldersync.php

@@ -256,6 +256,9 @@ class FolderSync extends RequestProcessor {
                 self::$encoder->endTag();
                 self::$topCollector->AnnounceInformation(sprintf("Outgoing %d folders",$changeCount), true);
 
+                if ($changeCount == 0) {
+                    self::$deviceManager->CheckFolderData();
+                }
                 // everything fine, save the sync state for the next time
                 if ($synckey == $newsynckey) {
                     self::$deviceManager->GetStateManager()->SetSyncState($newsynckey, $newsyncstate);

src/lib/request/ping.php

@@ -73,6 +73,11 @@ class Ping extends RequestProcessor {
                 $pingstatus = SYNC_PINGSTATUS_FAILINGPARAMS;
                 self::$topCollector->AnnounceInformation("StateInvalidException: require PingParameters", true);
             }
+            elseif (self::$deviceManager->IsHierarchySyncRequired()) {
+                // we could be in a looping  - see LoopDetection->ProcessLoopDetectionIsHierarchySyncAdvised()
+                $pingstatus = SYNC_PINGSTATUS_FOLDERHIERSYNCREQUIRED;
+                self::$topCollector->AnnounceInformation("Potential loop detection: require HierarchySync", true);
+            }
             else {
                 // we do not have a ping status for this, but SyncCollections should have generated fake changes for the folders which are broken
                 $fakechanges = $sc->GetChangedFolderIds();
@@ -231,6 +236,7 @@ class Ping extends RequestProcessor {
                         self::$encoder->endTag();
                         if (empty($fakechanges))
                             self::$topCollector->AnnounceInformation(sprintf("Found change in %s", $sc->GetCollection($folderid)->GetContentClass()), true);
+                        self::$deviceManager->AnnounceProcessStatus($folderid, SYNC_PINGSTATUS_CHANGES);
                     }
                 }
                 self::$encoder->endTag();

src/lib/request/sync.php

@@ -747,6 +747,7 @@ class Sync extends RequestProcessor {
         // global status
         // SYNC_COMMONSTATUS_* start with values from 101
         if ($status != SYNC_COMMONSTATUS_SUCCESS && ($status == SYNC_STATUS_FOLDERHIERARCHYCHANGED || $status > 100)) {
+            self::$deviceManager->AnnounceProcessStatus($folderid, $status);
             $this->sendStartTags();
             self::$encoder->startTag(SYNC_STATUS);
                 self::$encoder->content($status);
@@ -854,6 +855,7 @@ class Sync extends RequestProcessor {
                             self::$topCollector->AnnounceInformation(sprintf("StatusException code: %d", $status), $this->singleFolder);
                             $this->saveMultiFolderInfo("exception", "StatusException");
                         }
+                        self::$deviceManager->AnnounceProcessStatus($spa->GetFolderId(), $status);
                     }
                 }
             }