unable to resolve the user / random sync to outlook



  • 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


  • Kopano

    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



  • 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


  • Kopano

    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



  • 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


  • Kopano

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



  • 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


  • Kopano

    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



  • 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


  • Kopano

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



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


  • Kopano

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


  • Kopano

    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


Log in to reply
 

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.