Exception : Timeout forced after due to other process - code: 3

sbourdette

Hello,

I have a recurrent error in my log for many users.
It seems that 2 processes a running at the same time for the same user and the same device.

Error message :

30/01/2018 11:09:10 [ 9254] [ INFO] [s@b.com] [secxxxxxxxxxx] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 308s from 830s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
30/01/2018 11:18:33 [ 9254] [ INFO] [s@b.com] [secxxxxxxxxxx] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 307s from 830s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
30/01/2018 11:23:38 [ 9304] [ INFO] [s@b.com] [secxxxxxxxxxx] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 307s from 830s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579

Find in attachment debug log for the two processes 9254 and 9304

I’m running z-push 2.3.8 with zimbra backend 67
Zimbra : Release 8.7.9.GA.1794.UBUNTU16.64 UBUNTU16_64 FOSS edition

Regards

Sylvain

sbourdette

@sbourdette

debugfile

Manfred

Hi Sylvain,

it’s not an error. Z-Push recognises if a device opens a second Ping connection and terminates the previous one which is now useless and just uses server resources.

Manfred

sbourdette

OK but it shouldn’t be tagged as Exception.

Manfred

Hi Sylvain,

The code throws an exception if this happens, hence the exception type in the log line. The decisive part is the log level which is INFO meaning that it isn’t an actual error.

Manfred

liverpoolfcfan

@sbourdette Do you know what the device types are?

Some clients start individual sync requests for each folder type and each one kicks off a Ping cycle when it finishes. This can result in multiple pings running for the same device. The z-push code kills off the extra ping connections.

liverpoolfcfan

@sbourdette @Manfred

The other problem I see in your logs is that the WBXML decoder is consistently having issues with the WBXML commands being sent by the device

30/01/2018 11:00:03 [ 9254] [WBXMLSTACK] [s@b.com] [secxxxxxxxxxx] WBXMLDecoder->getElementStartTag(): unmatched WBXML tag: ‘Ping:Ping’ matching ‘’ type ‘’ flags ‘’

This needs investigation by the z-push guys - but the extract from the logs you posted does not contain enough information

sbourdette

You can find complete debug file for this process here debug_zpush_wbxml.log

Manfred

Hi @liverpoolfcfan,

@liverpoolfcfan said in Exception : Timeout forced after due to other process - code: 3:

@sbourdette Do you know what the device types are?

Some clients start individual sync requests for each folder type and each one kicks off a Ping cycle when it finishes. This can result in multiple pings running for the same device. The z-push code kills off the extra ping connections.

Devices may issue Ping command without WBXML data. In such case the cached data of previous Ping commands is used.

When there’s no WBXML tag but Z-Push reads it (self::$decoder->getElementStartTag(SYNC_PING_PING)), there will be WBXMLSTACK log level output that the matching tag was not found. (For that matter every self::$decoder->getElementStartTag(TAG_NAME) call will generate such log entry if the tag is not available in the WBXML data). Therefore WBXMLSTACK log level is rarely necessary, WBXML is more than enough in almost all cases.

Manfred

liverpoolfcfan

If the device issues an empty ping - would hierarchy changes still be detected?

For example - if a device was pinging 10 folders repeatedly with empty pings always pulling the cached request, and during the ping cycle a new folder is added, does the code that would notify a hierarchy sync needed ever get triggered, or is is skipped?

Manfred

Hi @liverpoolfcfan ,

yes, they should because the backend is responsible for detecting changes and the request class only returns them. E.g. in Kopano backend if there were hierarchy changes we just add a notification in ChangesSync function:

public function ChangesSink($timeout = 30) {
        $notifications = array();
        $hierarchyNotifications = array();
... content changes stuff and also add hierarchy changes to $hierarchyNotifications
        if (!empty($hierarchyNotifications)) {
            $hash = $this->getHierarchyHash();
            if ($hash !== $this->changesSinkHierarchyHash) {
                ZLog::Write(LOGLEVEL_DEBUG, sprintf("BackendKopano->ChangesSink() Hierarchy notification, pending validation. New hierarchyHash: %s", $hash));
                $notifications[] = IBackend::HIERARCHYNOTIFICATION;
                $this->changesSinkHierarchyHash = $hash;
            }
        }
        return $notifications;
    }

The rest is then handled by ping.

Manfred

liverpoolfcfan

@manfred - For some time the code in the zimbra backend to try to recognize and handle Hierarchy changes is

            if ( isset( $notify['created']['folder'] ) || isset( $notify['deleted']['folder'] )) {
                ZLog::Write(LOGLEVEL_DEBUG, 'Zimbra->ChangesSink(): ' .  'Folder Creation/Deletion - FolderSync Required ' );
                if (defined('SyncCollections::HIERARCHY_CHANGED')) {
                    throw new StatusException("Zimbra->ChangesSink(): HierarchySync required.", SyncCollections::HIERARCHY_CHANGED);
                } else {
                    throw new StatusException("Zimbra->ChangesSink(): HierarchySync required.", SyncCollections::ERROR_WRONG_HIERARCHY);
                }
            }

Does that still work with the latest 2.3/2.4 z-push, or do I need to write something similar to what you have in your code above instead?

My concern is that the ping cache might not be getting cleaned up correctly

Manfred

@liverpoolfcfan the last bigger change in ping.php was https://jira.z-hub.io/browse/ZP-1251, but I don’t think it affects the hierarchy changes. For Z-Push 2.4. we haven’t changed anything there, so I suppose your code should still get hierarchy changes in ping.

Manfred

liverpoolfcfan

@manfred
If I want to handle it in the same way as you are doing is this all I need to do whan I detect a change

                $notifications[] = IBackend::HIERARCHYNOTIFICATION;

Manfred

@liverpoolfcfan yes, that would be all if you detect hierarchy changes in your backend. The code then checks again if the hierarchy changed by configuring a hierarchy exporter. If that’s the case it will throw StatusException with SyncCollections::HIERARCHY_CHANGED like it’s in the zimbra backend now. However in kopano we sometimes had/have not relevant hierarchy change notifications and adding the IBackend::HIERARCHYNOTIFICATION $notifications helped to solve those and spared some unnecessary requests.

Manfred