Deleting Contact - DeleteAsMoves value not passed to backend

[liverpoolfcfan]

In trying to address a user’s question about DeleteAsMoves, I have added some additional logging to z-push and to the zimbra backend. You can see here that the request comes in with DeleteAsMoves FALSE but by the time the backend DeleteMessage is called, the value is TRUE. Is there a potential problem with where SyncParameters->UseCPO(‘DEFAULT’) is called for the second time (in FilterType processing)? Could it be resetting the value to TRUE after it has already been decoded from the input?

09/01/2020 10:56:08 [10430] [WBXML] I  <Synchronize>
09/01/2020 10:56:08 [10430] [WBXML] I   <Folders>
09/01/2020 10:56:08 [10430] [WBXML] I    <Folder>
09/01/2020 10:56:08 [10430] [WBXML] I     <SyncKey>
09/01/2020 10:56:08 [10430] [WBXML] I      {f0f58f53-dcad-4f37-8e48-76800b8af292}46
09/01/2020 10:56:08 [10430] [WBXML] I     </SyncKey>
09/01/2020 10:56:08 [10430] [WBXML] I     <FolderId>
09/01/2020 10:56:08 [10430] [WBXML] I      f7
09/01/2020 10:56:08 [10430] [WBXML] I     </FolderId>
09/01/2020 10:56:08 [10430] [DEBUG] FileStateMachine->GetState() read '1001' bytes from file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-fd'
09/01/2020 10:56:08 [10430] [DEBUG] SyncParameters->UseCPO('DEFAULT')
09/01/2020 10:56:08 [10430] [DEBUG] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'f7', returning as is.
09/01/2020 10:56:08 [10430] [DEBUG] SyncCollections->AddCollection(): Folder id 'f7' : ref. PolicyKey '-1', ref. Lifetime '3540', last sync at '1578567246'
09/01/2020 10:56:08 [10430] [DEBUG] SyncCollections->AddCollection(): Updated reference PolicyKey '-1', reference Lifetime '3540', Last sync at '1578567246'
09/01/2020 10:56:08 [10430] [WBXML] I     <DeletesAsMoves>
09/01/2020 10:56:08 [10430] [DEBUG] Found SYNC_DELETESASMOVES
09/01/2020 10:56:08 [10430] [WBXML] I      0
09/01/2020 10:56:08 [10430] [DEBUG] Found SYNC_DELETESASMOVES has a value
09/01/2020 10:56:08 [10430] [WBXML] I     </DeletesAsMoves>
09/01/2020 10:56:08 [10430] [DEBUG] SYNC_DELETESASMOVES []
09/01/2020 10:56:08 [10430] [WBXML] I     <GetChanges>
09/01/2020 10:56:08 [10430] [WBXML] I      0
09/01/2020 10:56:08 [10430] [WBXML] I     </GetChanges>
09/01/2020 10:56:08 [10430] [WBXML] I     <WindowSize>
09/01/2020 10:56:08 [10430] [WBXML] I      512
09/01/2020 10:56:08 [10430] [WBXML] I     </WindowSize>
09/01/2020 10:56:08 [10430] [WBXML] I     <Options>
09/01/2020 10:56:08 [10430] [WBXML] I      <FilterType>
09/01/2020 10:56:08 [10430] [DEBUG] SyncParameters->UseCPO('DEFAULT')
09/01/2020 10:56:08 [10430] [WBXML] I       0
09/01/2020 10:56:08 [10430] [WBXML] I      </FilterType>
09/01/2020 10:56:08 [10430] [WBXML] I      <AirSyncBase:BodyPreference>
09/01/2020 10:56:08 [10430] [WBXML] I       <AirSyncBase:Type>
09/01/2020 10:56:08 [10430] [WBXML] I        1
09/01/2020 10:56:08 [10430] [WBXML] I       </AirSyncBase:Type>
09/01/2020 10:56:08 [10430] [WBXML] I       <AirSyncBase:AllOrNone>
09/01/2020 10:56:08 [10430] [WBXML] I        1
09/01/2020 10:56:08 [10430] [WBXML] I       </AirSyncBase:AllOrNone>
09/01/2020 10:56:08 [10430] [WBXML] I      </AirSyncBase:BodyPreference>
09/01/2020 10:56:08 [10430] [WBXML] I     </Options>
09/01/2020 10:56:08 [10430] [WBXML] I     <Perform>
09/01/2020 10:56:08 [10430] [WBXML] I      <Remove>
09/01/2020 10:56:08 [10430] [WBXML] I       <ServerEntryId>
09/01/2020 10:56:08 [10430] [WBXML] I        394914
09/01/2020 10:56:08 [10430] [WBXML] I       </ServerEntryId>
09/01/2020 10:56:08 [10430] [WBXML] I      </Remove>
09/01/2020 10:56:08 [10430] [DEBUG] Sync->getImporter(): initialize importer
09/01/2020 10:56:08 [10430] [DEBUG] Sync->loadStates(): loading states for folder 'f7'
09/01/2020 10:56:08 [10430] [DEBUG] FileStateMachine->GetState() read '62478' bytes from file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-46'
09/01/2020 10:56:08 [10430] [DEBUG] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/5/d/060d200c93dd47409ca35d3201ec3ad5-f0f58f53-dcad-4f37-8e48-76800b8af292-fs-45'
09/01/2020 10:56:08 [10430] [DEBUG] ZPush::GetAdditionalSyncFolderStore('f7'): 'false'
09/01/2020 10:56:08 [10430] [DEBUG] LoopDetection->SetSyncStateUsage(): uuid: f0f58f53-dcad-4f37-8e48-76800b8af292  counter: 46
09/01/2020 10:56:08 [10430] [DEBUG] Zimbra->StatMessage(): START StatMessage (fid = f7 - id = 394914 )
09/01/2020 10:56:08 [10430] [DEBUG] Zimbra->StatMessage(): END StatMessage CONTACT
09/01/2020 10:56:08 [10430] [DEBUG] Zimbra->DeleteMessage(): START DeleteMessage { folderid = f7; id = 394914; contentParameters = OBJECT }
09/01/2020 10:56:08 [10430] [DEBUG] Zimbra->DeleteMessage(): DeletesAsMoves = [1]
09/01/2020 10:56:08 [10430] [DEBUG] Zimbra->DeleteMessage(): DeleteMessage - CLEARING CACHE for folder [f7]

[liverpoolfcfan]

Same happens for Calendar, and I would assume Tasks/Notes too

[Manfred]

Hi @liverpoolfcfan

I don’t think it happens at SyncParameters->UseCPO(‘DEFAULT’), but someone would need to debug it more to say for sure.

What is the downside of it? The item is move to wastebasket instead of being really deleted?

Manfred

[liverpoolfcfan]

Yes. It doesn’t get deleted.

I am running the latest beta code and am happy to add debug instructions and test if you tell me where

[Manfred]

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

[liverpoolfcfan]

@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.

[Manfred]

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

[liverpoolfcfan]

@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]

@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

[liverpoolfcfan]

@Manfred Any thoughts on this?

[Manfred]

Hi @liverpoolfcfan,

I didn’t have time yet to look into it more extensively.

Manfred

[liverpoolfcfan]

@Manfred Do you know if there is any fix in z-push since February that would address this issue?

[Manfred]

Hi @liverpoolfcfan

not that I’m aware of.

Manfred

[liverpoolfcfan]

@manfred Is there a JIRA ticket for it?

[Manfred]

Hi @liverpoolfcfan,

I looked through the JIRA issues and didn’t find any related to it, so probably not.

Manfred

[liverpoolfcfan]

@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.

[Manfred]

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

[liverpoolfcfan]

@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.”

[liverpoolfcfan]

@manfred
So, as far as I can make out. SyncParameters is an object, and it contains a member array contentparamaters

Both 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?

[Manfred]

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