unable to resolve the user / random sync to outlook

Coffee_is_life

Update:

You said the WBXML protokoll is “particulary interesting”. I’ve got another user with this problem… Mail is visible in Webapp, outlook dont know it. Click the message and/or mark it with a flag, Z-push will sync it immentally as “NewItem”.

WBXML-Log:

10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] HandleSync(): Start Output
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe70c7500000000'): 'false'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] KopanoBackend->GetFolderStat() fetched status information of 1229 folders for store '<ThisUser>'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] SyncParameters->IsExporterRunRequired(): true - current: 1494402926/30/1/19 - saved: 1494402858/30/1/19 - expiring: 2017-06-10 09:54:21
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] Sync->loadStates(): loading states for folder 'U4a1c3'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/3/8/63ead8f3d61b4016afdd3425b6d68583-2812d244-da52-4a92-a432-10d588d2cedd-24'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe70c7500000000'): 'false'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe70c7500000000'): 'false'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ExportChangesICS->Config() initialized with state: 0x903101000e91a402
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ExportChangesICS->InitializeExporter() successfully. 2 changes ready to sync for 'f0bc882a8e0f410aa9765bd325976fe70c7500000000'.
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] LoopDetection->ProcessLoopDetectionAddStatus: 'U4a1c3' with status 1
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] Folder type: Email
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O  <Synchronize>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O   <Folders>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O    <Folder>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     <SyncKey>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     {2812d244-da52-4a92-a432-10d588d2cedd}25
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     </SyncKey>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     <FolderId>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     U4a1c3
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     </FolderId>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     <Status>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     1
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     </Status>
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] LoopDetection->Detect(): folderid:'U4a1c3' uuid:'2812d244-da52-4a92-a432-10d588d2cedd' counter:'24' max:'512' queued:'2'
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     <MoreAvailable/>
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: 'f0bc882a8e0f410aa9765bd325976fe79fc197000000', parentsourcekey: 'f0bc882a8e0f410aa9765bd325976fe70c7500000000', entryid: '000000000837f653e50844a4af1997e3cab8661601000000050000000a1bff44bf21417295fe571d455a31a400000000'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe70c7500000000'): 'false'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] BodyPreference types: 4
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] GetBodyPreferenceBestMatch: 4
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] bpo: truncation size:'0', allornone:'1', preview:'0'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #2785 streamlength: 12528
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O     <Perform>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O      <Add>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O       <ServerEntryId>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O       U4a1c3:f0bc882a8e0f410aa9765bd325976fe79fc197000000
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O       </ServerEntryId>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O       <Data>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:To>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        " Fenn (andreas.fenn@<partnerdomain>.de)" <andreas.fenn@<partnerdomain>.de>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:To>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:Cc>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        "ThisUser" <This.User@<OurDomain>>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:Cc>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:From>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        "Bernd Baumann" <bernd.baumann@<OurDomain>>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:From>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:Subject>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        Lagerung Katalysator
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:Subject>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:DateReceived>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        2017-03-22T16:29:16.000Z
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:DateReceived>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:DisplayTo>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         Fenn (andreas.fenn@<partnerdomain>.de)
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:DisplayTo>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:Importance>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        1
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:Importance>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:Read>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        1
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:Read>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:MessageClass>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        IPM.Note
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:MessageClass>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:InternetCPID>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        28591
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:InternetCPID>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <AirSyncBase:Body>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         <AirSyncBase:Type>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         4
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         </AirSyncBase:Type>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         <AirSyncBase:EstimatedDataSize>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         12528
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         </AirSyncBase:EstimatedDataSize>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         <AirSyncBase:Truncated>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         0
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         </AirSyncBase:Truncated>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         <AirSyncBase:Data>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         <<< written 12528 of 12528 bytes of plain data >>>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O         </AirSyncBase:Data>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </AirSyncBase:Body>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:ContentClass>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        urn:content-classes:message
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </POOMMAIL:ContentClass>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <POOMMAIL:Flag/>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        <AirSyncBase:NativeBodyType>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        2
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O        </AirSyncBase:NativeBodyType>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O       </Data>
10/05/2017 09:55:27 [18136] [WBXML] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] O      </Add>
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] PHPWrapper->ImportMessageChange(): change for: 'U4a1c3:f0bc882a8e0f410aa9765bd325976fe79fc197000000'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: 'f0bc882a8e0f410aa9765bd325976fe70b3697000000', parentsourcekey: 'f0bc882a8e0f410aa9765bd325976fe70c7500000000', entryid: '000000000837f653e50844a4af1997e3cab86616010000000500000004761608b82347eda6672aa22044f51e00000000'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe70c7500000000'): 'false'
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] BodyPreference types: 4
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] GetBodyPreferenceBestMatch: 4
10/05/2017 09:55:27 [18136] [DEBUG] [<ThisUser>] [63ead8f3d61b4016afdd3425b6d68583] bpo: truncation size:'0', allornone:'1', preview:'0'

This is a messages with this problem. I tried to anonymize it as less as possible. (i tried with another one, but the post got too big) - WBXML-OUT data alone is too long (56512 characters)

Is there an easy way to provide you the info? - Maybe i could send the whole log (7.3MB from 3 minutes) or the log from this second (09:55:27) with WBXML-OUT/IN - additional i will open a ticket now

I think more information is is good :)

Coffee_is_life

Sebastian

I got your log. I suggest that we continue to discuss this publicly here. If there is something sensitive we can fallback to the support ticket.

I don’t see anything out of the ordinary in your log.
Not a daily setting I see is that you limit the sync to 6 months. The emails are newer so they should be inside the sync window.
The only thing I see in the log is that the messages are exported. Are these older emails that were reimported at a later point (like backup restore)?

So, this seems not to be related to Z-Push or KOE, it’s Kopanos ICS mechanism that seems just not to be exporting the emails.

Can you reproduce this on other mobile devices as well? Like, if you sync an iOS with unlimited email (so it get’s limited to 6 months on the server). Are these emails then on the phone? Please create a full wbxml log for this user (could be via $specialLogUsers).
Then check if the serverids from the messages (like U4a1c3:f0bc882a8e0f410aa9765bd325976fe70b3697000000 from the log you’ve sent) appear in the log when you sync for the first time).
I would guess that they don’t (because ICS doesn’t export them for some reason).

Coffee_is_life

I will get a phone later this day to sync this user.

Is there a way to get only this user with a specific deviceID logged or will i get a WBXML from this user and all devices?

Coffee_is_life

Coffee_is_life

@Coffee_is_life said in unable to resolve the user / random sync to outlook:

I will get a phone later this day to sync this user.

Is there a way to get only this user with a specific deviceID logged or will i get a WBXML from this user and all devices?

Coffee_is_life

Nevermind, i will log both Devices with “LOGLEVEL_DEVICEID”. Are you interested in both devices or should i do something like “cat /var/log/z-push/usernname.log |grep DEVICEID >> /var/log/user-deviceid.log” and give you only one specific deviceid-sync?

Coffee_is_life

Sebastian

When you log via specialLogUser the deviceid is logged, and yes, you can filter out logs for a specific device grepping for the deviceid.

Sebastian

This is just a hunch, but could you try to set

define('SYNC_FILTERTIME_MAX', SYNC_FILTERTYPE_ALL);

in your config? This should not be related, but I just observed that on another system that has some weird sync issues.

From your Android log: there is a folder “Unwanted” that the device tries to create immediately after profile setup. Is this something you did manually? Or is this your Android client?
The creation did not succeed and the mobile tries to recreate it over and over again.

Cheers,
Sebastian

Coffee_is_life

Hello again,

sorry for the long time no answer, but i thought this problem was fixed and forgot about the ticket…

I’ve got the same behaviours as described in my topic.
Nothing unusual in any logs, the server just wont export some mails till its properties gets changes in webapp/deskapp.
Mails from ie. yesterday popping up after deleting a mailitem in outlook. This is absolute random and sometimes hard for the employees to work with because some urgent mails just wont show.

im in contact with Mr. Stradinger and i will talk about this problem on next possibility.

Coffee_is_life

Sebastian

Do you still have SYNC_FILTERTIME_MAX set to 6 month? Did you try to set it to ALL to see if this changes anything?

Coffee_is_life

Since we got also a problem with “purge softdelete items” no, but im about to build a whole test environment with kopano, webapp and some clients, i will try this as soon as possible.

another question with older mails and purging: is there a simple way to delete all items older 180 days, doesnt matter if soft-deleted or not?

we got an archive-system with all mails stored and the users are used to it if they want to search old mails. If yes, the SYNC_FILTERTIME_MAX can be set to ALL without any Problems and we are reducing the db-data.

coffee_is_life

Sebastian

This can be done, but I do not know if there are any ready-to-use tools.
This can certainly be scripted with e.g. python-kopano.
I would recommend opening a separate thread for this.

Coffee_is_life

For all with such a problem:
i’ve got a script via subscription support to pruge the items outside of kopanos triggers and internal actions.

its a script called “purge-softdelete.py”, and deletes the items directly from db.
seems to work in test environment - i will provide info if this is also for the productive env.

one thing to mention: availible ram is getting lower and lower within the process and needs some time (about 1d to release the ressources or requires rebooting the server)

//EDIT: A bit late, but here info for productive Systems:
It works and solved the problem, but NEVER EVER start the purge with 30 days or something if you didnt purge for over half a year and the script want to delete over 1,8 mio elements ;)
start with 360 days and decrase 30 days with every purge.
Ignore the MAPI_E_DISK_ERROR’s, the script is searching for them and will try to redo the action afterwards. if you reached your desired days run it 3 till 4 times to eleminate all items, even with MAPI_E_DISK_ERROR…
And to mention, dont run the initial purge if users are active, the performance of db will decrase and the users will blame you ;(

coffee_is_life