z-push-2 Issues - build 805

[liverpoolfcfan]

Hi,

I have build 805 of z-push-2 from SVN, and have encountered a few issues.

requestprocessor.php

First major issue is with a clean slate WM 6.5 phone. I am porting the zimbra backend - but that is not relevant here as far as I can see.

The first folder to try to sync it's contents is the Contacts folder.

It gets a $collection as follows


23/09/2011 16:48:53 [26593] [vincents] [DEBUG] Collection [Array
(
[clientids] => Array
(
)

[modifyids] => Array
(
)

[removeids] => Array
(
)

[fetchids] => Array
(
)

[statusids] => Array
(
)

[class] => Contacts
[synckey] => 0
[collectionid] => f7
[cpo] => ContentParameters Object
(
[contentclass:private] => Contacts
[filtertype:private] =>
[truncation:private] => 9
[rtftruncation:private] =>
[mimesupport:private] =>
[mimetruncation:private] =>
)

[conflict] => 1
[windowsize] => 100
[syncstate] =>
)
]

At line 895

if($status == SYNC_STATUS_SUCCESS && (isset($collection["getchanges"]) || $collection["synckey"] == "0")) {

though $collection["getchanges"] is not set, it passes the test here because $collection["synckey"] == "0"

A new synckey is generated and added to the $collection

[newsynckey] => {34f75c76-c10a-4fa0-b690-ba927a23fba6}1


However, when we get down to line 1031

if($status == SYNC_STATUS_SUCCESS && isset($collection["getchanges"])) {

Only isset($collection["getchanges"] is checked. There is no allowance here for a first time sync. So the block to add the new contacts does not get executed, and the code subsequently bombs out at line 1062 because there is no syncstate.

I believe line 1031 needs to be changed to match line 895

if($status == SYNC_STATUS_SUCCESS && (isset($collection["getchanges"]) || $collection["synckey"] == "0")) {

in order for a first time sync to work.


diffbacknd.php

In diffbackend there are a couple of cosmetic logging bugs that caused me heartache while trying to figure out what the code was doing.

In
class ExportChangesDiff extends DiffState implements IExportChanges{

there are 3 different debug log entries that are prefixed with ImportChangesDiff - an obvious copy/paste error - but when you are new to this structure it has you looking in the wrong places to find out what is going wrong.

Line 568
ZLog::Write(LOGLEVEL_DEBUG,sprintf("ImportChangesDiff->InitializeExporter(): Initializing message diff engine. '%d' messages in state", count($this->syncstate)));

Line 593
ZLog::Write(LOGLEVEL_DEBUG, "ImportChangesDiff->InitializeExporter(): Initializing folder diff engine");

Line 605
ZLog::Write(LOGLEVEL_INFO, sprintf("ImportChangesDiff->InitializeExporter(): Found '%d' changes", count($this->changes) ));


Not Traced Yet

I have a third issue that I haven't been able to fully debug yet.

I have 400+ contacts - and the max window is 100 - but the sync keeps spinning on the first 100 contacts. It never goes on to 101-200, etc.

Vincent

[skummer]

Hi Vincent,

great that you are testing this!

About your issues:
When the mobile requests a full new sync (synckey = 0) then there should not be sent data back. The mobile just receives the new synckey with counter 1 but no objects.
What we have recently changed the code slightly so that the exporter gets indeed fully initialized ready to stream changes. That way we are able to save a fully valid state for {uuid}1. Before this was not done causing the exporter be be reinitialized on the next sync. In the case that the folder has no objects in it (namely: is empty) this caused trouble for the zarafa backend because on each sync of that folder a new exporter was registered with ICS.
So, right now the exporter gets fully initialized so the {uuid}1 is a fully valid state, not "" as it was before.
Indeed no changes are sent during that first request, but this is intentional.

I have fixed the wrong log outputs of the diff backend in r810. sorry for that!

About the other issue: which synckey does the mobile send for the request after you've sent it your first 100 contacts? Is it the new synckey? Or still the {uuid}1 (old one) ?
When the mobile does not understand your answer (e.g. broken contact/field) it just retries resending the same synckey again. This could explain the loop. Try forcing a maxitems window of 1, then it should sync the contacts one by one and just break at the invalid entry (which is most probably not one of the firsts).

Cheers,
Sebastian

[liverpoolfcfan]

Hi Sebastian,

The behaviour I was seeing was that the code basically bombed out with the GetState call as no state had been defined at the time. Are you saying it should have worked as it was in 805 - or have you made some changes since 805 that have addressed the problem I saw ?

Thanks on the log messages.

After I had posted earlier, and with my change in place for requestprocessor, I deleted the account from the phone, and deleted all state information from the server. I think it successfully synced all the contents at that stage - so it may have been a glitch caused by the initial problem. I will test again on Monday and comment back if I do still have a problem.

Vincent

[liverpoolfcfan]

Sebastian,

Sorry - I just realized I should have added log entries here too - but if you look over at my posting from earlier in the day in the General Discussion folder, the log entries are in there. I had posted up there to see if anyone had any ideas before finally getting to the bottom of the issue myself later and posting my findings here.

See this post ... http://z-push.sourceforge.net/phpbb/viewtopic.php?f=4&t=1599#p5944
Vincent

[liverpoolfcfan]

Not sure if this is a valid fix for every situation but this worked for me ... Hopefully this helps.

Maybe this change is undoing your intended change in terms of not initializing the exporter - but I found it necessary as without it, GetState() just crashes out. If indeed this is undoing your intended change - then perhaps there a missing call to SetState() somewhere in the code you had added ? because there is definitely no state available then it gets to the bottom of the HandleSync function.

Vincent

Near the end of the Sync function (around line 1060) is the following block of code

--------

// Save the sync state for the next time
if(isset($collection["newsynckey"])) {
if (isset($exporter) && $exporter)
$state = $exporter->GetState();

// nothing exported, but possibly imported
else if (isset($importer) && $importer)
$state = $importer->GetState();

// if a new request without state information (hierarchy) save an empty state
else if ($collection["synckey"] == "0")
$state = "";

if (isset($state) && $status == SYNC_STATUS_SUCCESS)
self::$deviceManager->SetSyncState($collection["newsynckey"], $state, $collection["collectionid"]);
else
ZLog::Write(LOGLEVEL_ERROR, sprintf("HandleSync(): error saving '%s' - no state information available", $collection["newsynckey"]));
}

--------

This is where it was bombing out as there is no State the first time through. I changed the code to check for the synckey "0" first as follows ...


-------

// Save the sync state for the next time
if(isset($collection["newsynckey"])) {
// if a new request without state information (hierarchy) save an empty state
if ($collection["synckey"] == "0")
$state = "";

else if (isset($exporter) && $exporter)
$state = $exporter->GetState();

// nothing exported, but possibly imported
else if (isset($importer) && $importer)
$state = $importer->GetState();

if (isset($state) && $status == SYNC_STATUS_SUCCESS)
self::$deviceManager->SetSyncState($collection["newsynckey"], $state, $collection["collectionid"]);
else
ZLog::Write(LOGLEVEL_ERROR, sprintf("HandleSync(): error saving '%s' - no state information available", $collection["newsynckey"]));
}

-------

[liverpoolfcfan]

The fix for requestprocessor.php I outlined in my last post above has also been used by user rufi over on the General Discussion board now.

http://z-push.sourceforge.net/phpbb/viewtopic.php?f=4&t=1611#p5985

Clearly the issue is independent of the backend being used - and is not zimbra specific.