Deleting Contact - DeleteAsMoves value not passed to backend


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

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

  • Kopano

    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


  • 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

  • Kopano

    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.

  • Kopano

    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?

  • Kopano

    Hi @liverpoolfcfan,

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

    Manfred