unable to resolve the user / random sync to outlook

Coffee_is_life

Hello community,

ive got a lot of log messages in z-push.log:

02/05/2017 09:24:11 [11302] [WARN] [<USERNAME>] /usr/share/z-push/backend/kopano/mapiprovider.php:2169 mapi_zarafa_getuser_by_name(): Unable to resolve the user: 8004010F (2)

The connection is via z-push to Outlook 2016 - so why is here a mapi-error? - thought with z-push mapi isnt used.

Furthermore, i’ve got another random error:
Mails are shown in Webapp correctly, but some are missing in Outlook. They wont show up until i click them in webapp. After clicking it, 3 seconds later they are popping up in Outlook.

Z-push local log for this event:

ZPushFolder: New item Posteingang: 0000000058D4985E1C4F3F4A887535B22AEF29CA0700C3B68E10F77511CEB4CD00AA00BBB6E600000000000C0000D9539C2261A6BB45B9DAB62C7081B3C10100200700000000
Debug: ZPushFolder: Folder changed in <USERNAME>@<DOMAIN>: Posteingang

in Z-Push Serverlog, the only message i get is:

[ INFO] [<USERNAME>] cmd='Sync' memory='15.03 MiB/17.00 MiB' time='19.10s' devType='WindowsOutlook' devId='d3576616669942358e3517d6726685e3' getUser='<USERNAME>' from='172.16.126.61' version='2.3.5+5' method='POST' httpcode='200'
[ INFO] [<USERNAME>] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/3/e/d3576616669942358e3517d6726685e3-c8cd054e-285e-4892-a149-3071879c0c06-fd' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119

thanks for help,

Coffee_is_life

Sebastian

Well, of course there is MAPI, but not directly between Outlook and the server. Outlook uses ActiveSync, a cousin of MAPI, and Z-Push converts ActiveSync into MAPI and the other way around.

This error btw pops up when you try to sync an email from a local user that has been deleted. In 2.3.6 there is a ticket to resolve the email address differently in these cases so you shouldn’t see this message anymore.

About the “missing” mails: Are they showing up in your z-push-admin output of this profile as “need attention” messages?

Cheers,
Seb

Coffee_is_life

Thanks @Sebastian ,

if i interpret it correctly, this is a know bug (resolve user) and will be fixed soon, so i can ignore this message - right?

About the missing mails: as far as i can see there is no “Attention needed” for this user. But i didnt check before the mail was synced. Now there is no error.

i started “z-push-admin -a resync -u <USERNAME> -d >DEVICEID>” and will report if i get the same error. - If yes i can tell if there is an attention needed in z-push-admin

---- waited for resync ----

After this resync there is no “attention needed” but i’ve not encountered this error (mail popping up after clicking) - i will reply if i get this again and with more information.

meanwhile i checked all users with Attention needed. do i need to do a full resync for a user with “Invalid states. Please force synchronization!” or is there another way to force sync?

Coffee_is_life

Sebastian

Well, it’s not a bug it’s more of an issue. But yes, you can ignore this message (and upgrade! :))

“Force a Sync” is quite different from resync! You can force a sync by hitting “send/receive” in outlook.
This is just an indication, no real error. As long as Outlook syncs fine everything is ok.
If you persistently get this message, it would be interesting to get a wbxml log for this user.

Cheers,
Sebastian

Coffee_is_life

Sooo, i’ve come up with some information:

The mails which arent in Outlook imnentally share one thing: iso-8859-15
did nearly 15 samplings and all headers contain “iso-8859-15?Q?”

header:

Subject: =?iso-8859-15?Q?Erinnerung=3A_Genehmigungsaufgabe_f=FCr_Eingangsr?=
 =?iso-8859-15?Q?echnung__547652_von_<KUNDE>_bis_27=2E04=2E?=
 =?iso-8859-15?Q?2017_pr=FCfen?=
From: =?iso-8859-15?Q?<NAME>?= <sendermail@domain>
To: =?iso-8859-15?Q?>RECE_NAME>?= <recipient.name@domain>

to prove this i checked some without problems:

Subject: AW: Rechnung 
From: =?utf-8?Q?<sender_name>?= <sender_mail>
To: =?utf-8?Q?<recipient_name>?= <recipient_mail>

maybe something to do with the encoding.

The z-push-local log just shows that there is a new item and do his job of syncing.
i’ve configured a specific user wbxmllog, and will provide this information tomorrow.

Coffee_is_life

Sebastian

That shouldn’t be an issue, but if you have a log, please post it.
Is the message then ignored by loop detection?

Coffee_is_life

Server Entry ID: U87870:f0bc882a8e0f410aa9765bd325976fe75f3b9d000000
Subject was edited for anonymization

This specific mail didnt appear in Outlook 2016. After marking it via webapp with a red flag, it pops up in outlook.

z-push-local log:

2017/05/04 09:39:01.821 (1,VSTA_Main): Trace: ZPushFolder: New item Posteingang: 0000000055E6FA70D3D09E42BC58CC22849F16B40700C3B68E10F77511CEB4CD00AA00BBB6E600000000000C0000D9539C2261A6BB45B9DAB62C7081B3C10100E31000000000
2017/05/04 09:39:01.837 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Posteingang
2017/05/04 09:39:01.837 (1,VSTA_Main): Trace: ZPushWatcher: Folder changed: Posteingang
2017/05/04 09:39:01.837 (1,VSTA_Main): Debug: ZPushWatcher: Folder event: Posteingang, ReplyFlags:MailItem, False
2017/05/04 09:39:01.853 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Posteingang
2017/05/04 09:39:01.853 (1,VSTA_Main): Trace: ZPushWatcher: Folder changed: Posteingang
2017/05/04 09:39:01.853 (1,VSTA_Main): Debug: ZPushWatcher: Folder event: Posteingang, ReplyFlags:MailItem, False
2017/05/04 09:39:09.534 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Posteingang
2017/05/04 09:39:09.534 (1,VSTA_Main): Trace: ZPushWatcher: Folder changed: Posteingang
2017/05/04 09:39:09.534 (1,VSTA_Main): Debug: ZPushWatcher: Folder event: Posteingang, ReplyFlags:MailItem, False
2017/05/04 09:39:09.550 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:39:09.565 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:43:34.057 (1,VSTA_Main): Trace: ReplyFlags: Reply header: 103/U87870:f0bc882a8e0f410aa9765bd325976fe762839e000000/U87870
2017/05/04 09:43:34.073 (1,VSTA_Main): Trace: SendAs: Responding to mail, checking
2017/05/04 09:43:34.073 (1,VSTA_Main): Trace: SendAs: Checking ZPush: <user>@<domain>
2017/05/04 09:43:34.073 (1,VSTA_Main): Trace: SendAs: Checking, Parent folder: Posteingang
2017/05/04 09:43:34.073 (1,VSTA_Main): Trace: SharedFolders: GetSharedFolder1: U87870
2017/05/04 09:43:34.089 (1,VSTA_Main): Trace: SendAs: Not a shared folder
2017/05/04 09:43:34.619 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Posteingang
2017/05/04 09:43:34.619 (1,VSTA_Main): Trace: ZPushWatcher: Folder changed: Posteingang
2017/05/04 09:43:34.619 (1,VSTA_Main): Debug: ZPushWatcher: Folder event: Posteingang, ReplyFlags:MailItem, False
2017/05/04 09:43:34.635 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:43:34.993 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:45:26.223 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:45:26.347 (1,VSTA_Main): Trace: ZPushFolder: Changed item Posteingang
2017/05/04 09:45:26.347 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Postausgang
2017/05/04 09:45:26.347 (1,VSTA_Main): Debug: ZPushFolder: Folder change on unreported folder in <user>@<domain>: Postausgang, 0000000055E6FA70D3D09E42BC58CC22849F16B40100C3B68E10F77511CEB4CD00AA00BBB6E600000000000D0000, <user>@<domain>
2017/05/04 09:45:26.363 (1,VSTA_Main): Trace: ZPushFolder: Excluding child on <user>@<domain>: \\<user>@<domain>\Postausgang
2017/05/04 09:45:26.363 (2,): Warning: MailItemWrapper: Undisposed wrapper:    at Acacia.Stubs.OutlookWrappers.ComWrapper`1..ctor(ItemType item)
   at Acacia.Stubs.OutlookWrappers.Mapping.CreateWrapper(Object o, Boolean mustRelease)
   at Acacia.Stubs.OutlookWrappers.Mapping.WrapOrDefault[Type](Object o, Boolean mustRelease)
   at Acacia.Utils.MailEvents.MailEventHooker.HandleReplyAll(Object response, Boolean& cancel)
   at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
   at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
   at System.Delegate.DynamicInvokeImpl(Object[] args)
   at System.Runtime.InteropServices.ComEventsMethod.DelegateWrapper.Invoke(Object[] args)
   at System.Runtime.InteropServices.ComEventsMethod.Invoke(Object[] args)
   at System.Runtime.InteropServices.ComEventsSink.System.Runtime.InteropServices.NativeMethods.IDispatch.Invoke(Int32 dispid, Guid& riid, Int32 lcid, INVOKEKIND wFlags, DISPPARAMS& pDispParams, IntPtr pvarResult, IntPtr pExcepInfo, IntPtr puArgErr)

2017/05/04 09:45:28.204 (1,VSTA_Main): Debug: ZPushFolder: Folder changed in <user>@<domain>: Postausgang

WBXML:

04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] HandleSync(): Start Output
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a17000000000'): 'false'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] KopanoBackend->GetFolderStat() fetched status information of 1069 folders for store '<user>'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] SyncParameters->IsExporterRunRequired(): true - current: 1493886974/12/0/357 - saved: 1493885503/12/0/357 - expiring: 2017-06-04 10:11:47
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] Sync->loadStates(): loading states for folder 'U87870'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] FileStateMachine->GetState() read '15' bytes from file: '/var/lib/z-push/2/a/378be1ea7754413a91dc020896d2e7a2-fa962d59-7d89-43ed-b10a-7155f427109a-903'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a17000000000'): 'false'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a17000000000'): 'false'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ExportChangesICS->Config() initialized with state: 0x0afb00003abfa002
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ExportChangesICS->InitializeExporter() successfully. 1 changes ready to sync for 'f0bc882a8e0f410aa9765bd325976fe7a17000000000'.
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] LoopDetection->ProcessLoopDetectionAddStatus: 'U87870' with status 1
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] Folder type: Email
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O  <Synchronize>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O   <Folders>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O    <Folder>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     <SyncKey>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     {fa962d59-7d89-43ed-b10a-7155f427109a}904
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     </SyncKey>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     <FolderId>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     U87870
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     </FolderId>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     <Status>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     1
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     </Status>
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] LoopDetection->Detect(): folderid:'U87870' uuid:'fa962d59-7d89-43ed-b10a-7155f427109a' counter:'903' max:'512' queued:'1'
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     <MoreAvailable/>
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] PHPWrapper->ImportMessageChange(): Getting message from MAPIProvider, sourcekey: 'f0bc882a8e0f410aa9765bd325976fe75f3b9d000000', parentsourcekey: 'f0bc882a8e0f410aa9765bd325976fe7a17000000000', entryid: '00000000740b62bdf91048248b901ef254689cd20100000005000000490b65f18ecd447a9586e3f50c7ff34600000000'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a17000000000'): 'false'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] BodyPreference types: 4
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] GetBodyPreferenceBestMatch: 4
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] bpo: truncation size:'0', allornone:'1', preview:'0'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] MAPIStreamWrapper::stream_open(): initialized mapistream: Resource id #4861 streamlength: 20465
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     <Perform>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O      <Add>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O       <ServerEntryId>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O       U87870:f0bc882a8e0f410aa9765bd325976fe75f3b9d000000
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O       </ServerEntryId>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O       <Data>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:To>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        "<userX>" <<userX>@<domain>>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:To>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:Cc>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        "<userV>" <<userV>@<domain>>, "<user>" <<user>@<domain>>, "<userZ>" <<userZ>@<domain>>, "<userT>" <<userT>@<domain>>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:Cc>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:From>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        "<userY>" <<userY>@<domain>>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:From>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:Subject>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <~SUBJECT ANONYMIZED - CONTAINS NAMES~>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:Subject>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:DateReceived>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        2017-04-25T18:22:49.000Z
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:DateReceived>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:DisplayTo>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <userX>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:DisplayTo>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:Importance>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        1
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:Importance>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:Read>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        1
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:Read>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:MessageClass>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        IPM.Note
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:MessageClass>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:InternetCPID>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        65001
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:InternetCPID>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <AirSyncBase:Body>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <AirSyncBase:Type>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         4
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         </AirSyncBase:Type>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <AirSyncBase:EstimatedDataSize>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         20465
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         </AirSyncBase:EstimatedDataSize>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <AirSyncBase:Truncated>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         0
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         </AirSyncBase:Truncated>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <AirSyncBase:Data>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <<< written 20465 of 20465 bytes of plain data >>>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         </AirSyncBase:Data>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </AirSyncBase:Body>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:ContentClass>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        urn:content-classes:message
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:ContentClass>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <POOMMAIL:Flag>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         <POOMMAIL:FlagStatus>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         2
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O         </POOMMAIL:FlagStatus>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </POOMMAIL:Flag>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        <AirSyncBase:NativeBodyType>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        2
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O        </AirSyncBase:NativeBodyType>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O       </Data>
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O      </Add>
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] PHPWrapper->ImportMessageChange(): change for: 'U87870:f0bc882a8e0f410aa9765bd325976fe75f3b9d000000'
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O     </Perform>
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a17000000000'): 'false'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] Sync()->setFolderStat() on U87870: 1493886974/12/0/357 expiring 2017-06-04 10:36:14
04/05/2017 10:36:14 [20077] [WBXML] [<user>] [378be1ea7754413a91dc020896d2e7a2] O    </Folder>
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] FileStateMachine->SetState() written 15 bytes on file: '/var/lib/z-push/2/a/378be1ea7754413a91dc020896d2e7a2-fa962d59-7d89-43ed-b10a-7155f427109a-904'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] SyncCollections->SaveCollection(): Data of folder 'U87870' changed
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] FileStateMachine->SetState() written 1091 bytes on file: '/var/lib/z-push/2/a/378be1ea7754413a91dc020896d2e7a2-fa962d59-7d89-43ed-b10a-7155f427109a-fd'
04/05/2017 10:36:14 [20077] [DEBUG] [<user>] [378be1ea7754413a91dc020896d2e7a2] ZPush::GetAdditionalSyncFolderStore('f0bc882a8e0f410aa9765bd325976fe7a67000000000'): 'false'

seems like it caused a loop, but its not in z-push-admin -a list -u <user>: (did 5 min before and after the sync - same output)

Synchronized devices of user: <user>
-----------------------------------------------------
DeviceId:               378be1ea7754413a91dc020896d2e7a2
Device type:            WindowsOutlook
UserAgent:              Outlook/16.0 (16.0.7870.6521; C2R; x64)
ActiveSync version:     14.0
First sync:             2017-04-18 08:20
Last sync:              2017-05-04 10:50
Total folders:          128
Short folder Ids:       Yes
Synchronized folders:   120
Synchronized data:      Emails(114) Contacts(2) Calendars Notes Tasks GAB
Additional Folders:     2
        Shared     Email    SYSTEM         <folder> -.. Active
        Shared     Contact  SYSTEM         <another folder>     Active
Status:                 Not available
WipeRequest on:         not set
WipeRequest by:         not set
Wiped on:               not set
Policy name:            default
Kopano Outlook Extension:
        Version:        1.3.156
        Build:          343705345b7aef675e2e0a1aa37d011171b6cf2f
        Build Date:     2017-04-05 14:11
        Capabilities:   receiveflags,sendflags,oof,ooftime,sharedfolders,webapp,freebusy,gab,notes,secondarycontacts,sendas,signatures,debugsupport
Attention needed:       No errors known

And as you can see, the timestamp of this mail is

<POOMMAIL:DateReceived>
2017-04-25T18:22:49.000Z
</POOMMAIL:DateReceived>

This is happening to at least 3 user. - I think its more, but its hard to realize if something is missing. And i cant take proactive work here. Any suggestions?

Thanks,

Coffe_is_life

Sebastian

Seems you have a subscription. Please open a ticket via the portal (also include a link to this ticket).
We need more logs, these ones are edited too much. The lines at the end are particulary interesting (WBXML-IN/OUT) because they contain the raw data which we can use to debug.

Cheers,
Sebastian

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