Deleting Contact - DeleteAsMoves value not passed to backend
-
Hi liverpoolfcfan,
I’d start by logging $this->contentParameters value in checkCPO() function in syncparameters.php. Also what ContentParameters value is passed to the Zimbra importer.
Manfred
-
@Manfred Could it be caused by the following in sync.php
getImporter gets called passing $spa which has the correct value, and other values set from the Sync request
However, in that function the importer configuration function importer->ConfigContentParameters gets called with $spa-GetCPO() which appears to me to be loading the saved ContentParamaters from state, and ignoring any values that might have been set on the request.
-
Hi liverpoolfcfan,
did you add more debugs to check that? Could you post the log with $spa values before and after that ConfigContentParameters call?
Manfred
-
@Manfred I added the following logging in getImporter
$this->importer->Config($sc->GetParameter($spa, "state"), $spa->GetConflict()); // the CPO is also needed by the importer to check if imported changes are inside the sync window - see ZP-258 ZLog::Write(LOGLEVEL_DEBUG, "SPA [" . print_r( $spa, true) . "]" ); ZLog::Write(LOGLEVEL_DEBUG, "SYNC_DELETESASMOVES [" . $spa->GetDeletesAsMoves() . "]" ); ZLog::Write(LOGLEVEL_DEBUG, "SPA-GetCPO [" . print_r( $spa->GetCPO(), true) . "]" ); $this->importer->ConfigContentParameters($spa->GetCPO()); ZLog::Write(LOGLEVEL_DEBUG, "SPA [" . print_r( $spa, true) . "]" ); ZLog::Write(LOGLEVEL_DEBUG, "SYNC_DELETESASMOVES [" . $spa->GetDeletesAsMoves() . "]" );The output is as below …
You can see that SPA contains DeletesAsMoves with a value FALSE - correct.
But then the ConfigContentParameters is called with $spa->GetCPO - which has no DeletesAsMoves value set - so the unset value of TRUE gets applied.
This has no bearing on SPA which still has a value FALSE after the ConfigContentParameters call
BUT, the importer has been initialized with the incorrect settings.
16/01/2020 15:54:38 [20210] [DEBUG] Sync->getImporter(): initialize importer 16/01/2020 15:54:38 [20210] [DEBUG] Sync->loadStates(): loading states for folder 'f7' 16/01/2020 15:54:38 [20210] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-58' 16/01/2020 15:54:38 [20210] [DEBUG] FileStateMachine->GetState() read '62597' bytes from file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-59' 16/01/2020 15:54:38 [20210] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-fs-57' 16/01/2020 15:54:38 [20210] [DEBUG] ZPush::GetAdditionalSyncFolderStore('f7'): 'false' 16/01/2020 15:54:38 [20210] [DEBUG] SPA [SyncParameters Object ( [synckeyChanged:SyncParameters:private] => [confirmationChanged:SyncParameters:private] => 1 [currentCPO:SyncParameters:private] => DEFAULT [unsetdata:protected] => Array ( [uuid] => [uuidcounter] => [uuidnewcounter] => [counterconfirmed] => [folderid] => [backendfolderid] => [referencelifetime] => 10 [lastsynctime] => [referencepolicykey] => 1 [pingableflag] => [contentclass] => [deletesasmoves] => [conversationmode] => [windowsize] => 5 [contentparameters] => Array ( ) [foldersynctotal] => [foldersyncremaining] => [folderstat] => [folderstattimeout] => [movestate] => ) [SO_internalid:StateObject:private] => d08936c8c660 [data:protected] => Array ( [contentparameters] => Array ( [DEFAULT] => ContentParameters Object ( [unsetdata:protected] => Array ( [contentclass] => [foldertype] => [conflict] => [deletesasmoves] => 1 [filtertype] => [truncation] => [rtftruncation] => [mimesupport] => [conversationmode] => ) [synckeyChanged:ContentParameters:private] => [SO_internalid:StateObject:private] => beb94a07e92e [data:protected] => Array ( [truncation] => 9 [conflict] => 1 [filtertype] => 0 [bodypref] => Array ( [1] => BodyPreference Object ( [unsetdata:protected] => Array ( [truncationsize] => [allornone] => [preview] => ) [SO_internalid:StateObject:private] => ae784fc3820a [data:protected] => Array ( [allornone] => 1 ) [changed:protected] => ) ) [contentclass] => Contacts [conversationmode] => ) [changed:protected] => 1 ) ) [movestate] => [folderid] => f7 [backendfolderid] => f7 [contentclass] => Contacts [deletesasmoves] => [windowsize] => 512 [foldersynctotal] => 667 [foldersyncremaining] => 1 [uuid] => f0f58f53-dcad-4f37-8e48-76800b8af292 [uuidcounter] => 59 [counterconfirmed] => 1 [referencelifetime] => 3540 [referencepolicykey] => -1 [lastsynctime] => 1579189985 [folderstat] => Contacts-1-417667-451-1471-1129876-395310#c45aaa79 [folderstattimeout] => 1581858555 [pingableflag] => 1 ) [changed:protected] => 1 ) ] 16/01/2020 15:54:38 [20210] [DEBUG] SYNC_DELETESASMOVES [] 16/01/2020 15:54:38 [20210] [DEBUG] SPA-GetCPO [ContentParameters Object ( [unsetdata:protected] => Array ( [contentclass] => [foldertype] => [conflict] => [deletesasmoves] => 1 [filtertype] => [truncation] => [rtftruncation] => [mimesupport] => [conversationmode] => ) [synckeyChanged:ContentParameters:private] => [SO_internalid:StateObject:private] => beb94a07e92e [data:protected] => Array ( [truncation] => 9 [conflict] => 1 [filtertype] => 0 [bodypref] => Array ( [1] => BodyPreference Object ( [unsetdata:protected] => Array ( [truncationsize] => [allornone] => [preview] => ) [SO_internalid:StateObject:private] => ae784fc3820a [data:protected] => Array ( [allornone] => 1 ) [changed:protected] => ) ) [contentclass] => Contacts [conversationmode] => ) [changed:protected] => 1 ) ] 16/01/2020 15:54:38 [20210] [DEBUG] SPA [SyncParameters Object ( [synckeyChanged:SyncParameters:private] => [confirmationChanged:SyncParameters:private] => 1 [currentCPO:SyncParameters:private] => DEFAULT [unsetdata:protected] => Array ( [uuid] => [uuidcounter] => [uuidnewcounter] => [counterconfirmed] => [folderid] => [backendfolderid] => [referencelifetime] => 10 [lastsynctime] => [referencepolicykey] => 1 [pingableflag] => [contentclass] => [deletesasmoves] => [conversationmode] => [windowsize] => 5 [contentparameters] => Array ( ) [foldersynctotal] => [foldersyncremaining] => [folderstat] => [folderstattimeout] => [movestate] => ) [SO_internalid:StateObject:private] => d08936c8c660 [data:protected] => Array ( [contentparameters] => Array ( [DEFAULT] => ContentParameters Object ( [unsetdata:protected] => Array ( [contentclass] => [foldertype] => [conflict] => [deletesasmoves] => 1 [filtertype] => [truncation] => [rtftruncation] => [mimesupport] => [conversationmode] => ) [synckeyChanged:ContentParameters:private] => [SO_internalid:StateObject:private] => beb94a07e92e [data:protected] => Array ( [truncation] => 9 [conflict] => 1 [filtertype] => 0 [bodypref] => Array ( [1] => BodyPreference Object ( [unsetdata:protected] => Array ( [truncationsize] => [allornone] => [preview] => ) [SO_internalid:StateObject:private] => ae784fc3820a [data:protected] => Array ( [allornone] => 1 ) [changed:protected] => ) ) [contentclass] => Contacts [conversationmode] => ) [changed:protected] => 1 ) ) [movestate] => [folderid] => f7 [backendfolderid] => f7 [contentclass] => Contacts [deletesasmoves] => [windowsize] => 512 [foldersynctotal] => 667 [foldersyncremaining] => 1 [uuid] => f0f58f53-dcad-4f37-8e48-76800b8af292 [uuidcounter] => 59 [counterconfirmed] => 1 [referencelifetime] => 3540 [referencepolicykey] => -1 [lastsynctime] => 1579189985 [folderstat] => Contacts-1-417667-451-1471-1129876-395310#c45aaa79 [folderstattimeout] => 1581858555 [pingableflag] => 1 ) [changed:protected] => 1 ) ] 16/01/2020 15:54:38 [20210] [DEBUG] SYNC_DELETESASMOVES [] 16/01/2020 15:54:38 [20210] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f0f58f53-dcad-4f37-8e48-76800b8af292 counter: 59 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->StatMessage(): START StatMessage (fid = f7 - id = 395309 ) 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->SoapRequest(): SOAP Message: <soap:Envelope xmlns:soap="http://www.w3.org/2003/05/soap-envelope"> <soap:Header><context xmlns="urn:zimbra"> <authToken>0_97c43db35946f067ba81814f12a09c2a98d7c6f8_69643d33363a36626530303439342d386364352d343836632d393939312d3739646437313239393932623b6578703d31333a313537393237363437383137303b76763d313a343b747970653d363a7a696d6272613b753d313a613b7469643d393a3538323832383730373b76657273696f6e3d31343a382e382e31355f47415f333832393b</authToken> <session id="118698" /><format type="js" /> <userAgent name="Outlook/16.0 (16.0.12325.20144; x86)(...ec3ad5) devip=172.17.217.3 ZPZB" version="69" /> </context></soap:Header> <soap:Body><GetContactsRequest sync="1" xmlns="urn:zimbraMail"> <cn id="395309"/> </GetContactsRequest></soap:Body> </soap:Envelope> 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->SoapRequest(): SOAP response: {"Header":{"context":{"session":{"id":"118698","_content":"118698"},"change":{"token":1129876},"_jsns":"urn:zimbra"}},"Body":{"GetContactsResponse":{"cn":[{"id":"395309","l":"7","f":"","tn":"","t":"","md":1579189982,"ms":1129876,"d":1579189982000,"rev":1129876,"meta":[{}],"fileAsStr":"Me, Delete","_attrs":{"firstName":"Delete","lastName":"Me","fullName":"Me, Delete","email":"del.me@del.me"}}],"_jsns":"urn:zimbraMail"}},"_jsns":"urn:zimbraSoap"} 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->StatMessage(): END StatMessage CONTACT 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->DeleteMessage(): START DeleteMessage { folderid = f7; id = 395309; contentParameters = OBJECT } 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->DeleteMessage(): DeletesAsMoves = [1] 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->DeleteMessage(): DeleteMessage - CLEARING CACHE for folder [f7] 16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->isZimbraObjectInSyncInterval(): START isZimbraObjectInSyncInterval { folderid = f7; id = 395309; contentParameters = <hidden> } -
@liverpoolfcfan said in Deleting Contact - DeleteAsMoves value not passed to backend:
16/01/2020 15:54:38 [20210] [DEBUG] Zimbra->DeleteMessage(): DeletesAsMoves = [1]
You can see that the value passed from the importer to the backend is TRUE
-
@Manfred Any thoughts on this?
-
-
@Manfred Do you know if there is any fix in z-push since February that would address this issue?
-
-
@manfred Is there a JIRA ticket for it?
-
Hi @liverpoolfcfan,
I looked through the JIRA issues and didn’t find any related to it, so probably not.
Manfred
-
@manfred Can you please create a ticket for this?
The diffbackend needs access to this so that the zimbra and other backends based on diffbackend can make the appropriate requests move or delete the item.
-
Hi @liverpoolfcfan,
@liverpoolfcfan said in Deleting Contact - DeleteAsMoves value not passed to backend:
@manfred Can you please create a ticket for this?
The diffbackend needs access to this so that the zimbra and other backends based on diffbackend can make the appropriate requests move or delete the item.
I’ve created https://jira.z-hub.io/browse/ZP-1604. You should have the permissions to create JIRA issues as well. I can’t guarantee that I will have time to look into this issue any time soon, so if you have a solution for it, send us a pull request.
Manfred
-
@manfred Trying to take a look at this issue again.
Can you please explain why in syncparameters.php the $unsetdata array has
'deletesasmoves' => false,while the MS-ASCMD documentation states
“If the client wants to permanently delete items, the request MUST include the DeletesAsMoves element with a value of 0 (FALSE). A value of 1 (TRUE), which is the default, indicates that any deleted items are moved to the Deleted Items folder. The default is assumed when the DeletesAsMoves element is either empty or not present.”
-
@manfred
So, as far as I can make out. SyncParameters is an object, and it contains a member array contentparamatersBoth of these have a deletesasmoves member object in them. The Former has an unset default of false. The latter has a default of true - Not sure why?
During a Sync - the SyncParameters->deletesasmoves is read from the request (if present)
But, when the importChangesDiff.php function is called
$stat = $this->backend->DeleteMessage($this->folderid, $id, $this->contentparameters);it passes $this->contentparameters - whose member deletesasmoves never gets set - just the default “unset” value is there.
What exactly is the function of $contentparameters ?
Should syncParameters->contentparameters->deleteasmoves also be set when the DeletesAsMoves setting is read from a sync command?
-
Hi @liverpoolfcfan,
it was a long time ago since we implemented it and I don’t remember the details why we did it this way. I wouldn’t exclude that there’s a bug somewhere there, however we never saw any issues with it in the Kopano backend and as far as I know with the other backends.
ContentParameters class saves some options of the requested folder (the ones in the $unsetdata array, but it might actually be anything as we’re making a heavy usage of magic getters and setters).
Unfortunately I don’t have any time in the foreseeable future to dive deep into it. If you’d be able to solve it, the contributions are always welcome.
Manfred
-
@manfred
I finally got a few hours to debug through this. Bottom line isContentParameters class has a deletesasmoves property with a default “unset” value of true. This is never used anywhere in the z-push-develop source tree as far as I can see. So passing that property in the ContentParameters object to the backend functions is of zero value.
SyncParameters class has a deletesasmoves property with a default “unset” value of false. This is updated based on the presence of the DeletesAsMoves flag in the incoming sync collection. It is subsequently used to decide between calling ImportMessageMove or ImportMessageDeletion - so if backend->DeleteMessage gets called it is because the SyncCollection dictated that. So, the basic code logic is correct - and the ticket ZP-1604 should be closed on that basis.
However, there is one remaining issue - the default “unset” value of deletesasmoves in SyncParameters is set to false. This is incorrect according to the specification which states
“If the client wants to permanently delete items, the request MUST include the DeletesAsMoves element with a value of 0 (FALSE). A value of 1 (TRUE), which is the default, indicates that any deleted items are moved to the Deleted Items folder. The default is assumed when the DeletesAsMoves element is either empty or not present.”
I will open a separate ticket for that.
