Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

    Sync problem with default Android application

    Z-Push when using other backends
    6
    31
    5281
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • jsda
      jsda last edited by jsda

      Hi Manfred

      Thank you for responding!

      The z-push-admin list output is as follows

      Synchronized devices of user: test.user
-----------------------------------------------------
DeviceId:		android1506920854664
Device type:		samsungSMP
UserAgent:		samsungSMP600/7.1.2-EAS-2.0
ActiveSync version:	14.0
First sync:		2018-05-07 10:51
Last sync:		2018-05-07 10:52
Sync Period:		unlimited (0)
Total folders:		4
Short folder Ids:	No
Synchronized folders:	2
Synchronized data:	Emails(2) 
Additional Folders:	none
Status:			OK
WipeRequest on:		not set
WipeRequest by:		not set
Wiped on:		not set
Policy name:		default
Attention needed:	No errors known

      Please note that since previously posting those logs, I have rolled back my test server and done a fresh install of Z-Push from repositories … that is why first sync and last sync are just 1 minute apart. (By the way, I tested with php5.6 and got the same results).

      I haven’t looked at logcat until now. Here is the output when I send an email to test.user (I changed my domain name to example.com)

      
05-07 11:17:33.192  4951  3410 I Exchange: Changes found in: b781a510
05-07 11:17:33.194  4951  3410 I Exchange: Ping found changed folders for account 17
05-07 11:17:33.252  4951  3410 I Exchange: EasOperation requestSyncForMailboxes  Account {name=test.user@example.com, type=com.android.exchange}, Bundle[{__mailboxCount__=1, __mailboxId0__=1317}]
05-07 11:17:33.267  4951  3410 I Exchange: EasOperation requestSyncForMailboxes  Account {name=test.user@example.com, type=com.android.exchange}, Bundle[{__mailboxCount__=0}]
05-07 11:17:33.273  4951  3410 I Exchange: EasOperation requestSyncForMailboxes  Account {name=test.user@example.com, type=com.android.exchange}, Bundle[{__mailboxCount__=0}]
05-07 11:17:33.273  4951  3410 I Exchange: Ping task ending with status: 2
05-07 11:17:33.273  4951  3410 I Exchange: PSS pingEnd for account 17
05-07 11:17:33.274  4951  3410 I Exchange: PSS pingEnd, starting new ping acct:17.
05-07 11:17:33.280  4951  3410 I Exchange: requestPing EasOperation Account {name=test.user@example.com, type=com.android.exchange}, Bundle[{force=true, __push_only__=true}]
05-07 11:17:33.387  4951  3719 I Exchange: onPerformSync email: Bundle[{__mailboxCount__=1, __mailboxId0__=1317}]
05-07 11:17:33.405  4951  3720 I Exchange: onPerformSync calendar: Bundle[{__mailboxCount__=0}]
05-07 11:17:33.412  4951  3721 I Exchange: onPerformSync contacts starting Bundle[{__mailboxCount__=0}]
05-07 11:17:33.474  4951  3719 I Exchange: PSS syncStart for account acct:17
05-07 11:17:33.482  4951  3721 I Exchange: PSS syncStart for account acct:17
05-07 11:17:33.483  4951  3721 I Exchange: PSS Sync needs to wait: Ping: no, Pending tasks: 2 acct: 17
05-07 11:17:33.489  4951  3720 I Exchange: PSS syncStart for account acct:17
05-07 11:17:33.490  4951  3720 I Exchange: PSS Sync needs to wait: Ping: no, Pending tasks: 3 acct: 17
05-07 11:17:33.726 29741 31198 D Email   : Insert: content://com.android.email.provider/message
05-07 11:17:33.757 29741 31198 D Email   : Insert: content://com.android.email.provider/body
05-07 11:17:33.885 29741 29741 D BluetoothEmailBroadcastReceiver: Received com.android.mail.action.update_notification
05-07 11:17:34.012  4951  3719 I Exchange: PSS syncEnd for account acct:17
05-07 11:17:34.012  4951  3719 I Exchange: PSS Signalling a pending sync to proceed acct:17.
05-07 11:17:34.048  4951  3726 I Exchange: onPerformSync email: Bundle[{ignore_settings=true, force=true, ignore_backoff=true, __push_only__=true}]
05-07 11:17:34.062 29741  3725 I NotifUtils: sendSetNewEmailIndicator account: 55125872, folder: 70791782
05-07 11:17:34.095  4951  3726 I Exchange: PSS pushModify acct:17
05-07 11:17:34.095  4951  3726 I Exchange: PSS pushModify acct:17
05-07 11:17:34.096  4951  3726 I Exchange: PSS syncs still in progress acct:17
05-07 11:17:34.133 29741  3725 I NotifUtils: sendSetNewEmailIndicator account: 55125872, folder: 70791782
05-07 11:17:34.139 29741  3725 I NotifUtils: Validating Notification, mapSize: 1 getAttention: true ignoreUnobtrusive: true
05-07 11:17:34.156  4951  3721 W FolderSyncParser: Duplicate mailboxes found for account 17: 1
05-07 11:17:34.182 29741  3725 I NotifUtils: Showing notification with unreadCount of 1 and unseenCount of 1
05-07 11:17:34.209 29741 29755 D Email   : Delete: content://com.android.email.provider/mailbox
05-07 11:17:34.280 29741  3725 E NotifUtils: null from string in getWrappedFromString
05-07 11:17:34.281 29741  3725 E NotifUtils: Failed to load message
05-07 11:17:34.327 29741  3725 I NotifUtils: Account: 55125872 vibrate: false
05-07 11:17:34.327 29741  3725 I NotifUtils: New email in 55125872 vibrateWhen: false, playing notification: content://settings/system/notification_sound
05-07 11:17:34.367 29741  3725 I NotifUtils: Validating Notification, mapSize: 1 getAttention: true ignoreUnobtrusive: false
05-07 11:17:34.380  4004  3729 E MediaPlayer-JNI: JNIMediaPlayerFactory: bIsQCMediaPlayerPresent 0
05-07 11:17:34.380  4004  3729 E MediaPlayer-JNI: JNIMediaPlayerFactory: bIsQCMediaPlayerPresent 0
05-07 11:17:34.394 29741  3725 I NotifUtils: Unseen count doesn't match cursor count.  unseen: 1 cursor count: 0
05-07 11:17:34.394 29741  3725 I NotifUtils: validateNotifications - cancelling account 55125872 / folder -608682334
05-07 11:17:34.415  3609  3730 D NuPlayerDriver: notifyListener_l(0xb5dab080), (1, 0, 0), loop setting(0, 0)
05-07 11:17:34.417  4004  3729 D MediaPlayer: setSubtitleAnchor in MediaPlayer
05-07 11:17:34.423  3870 14139 I MediaFocusControl:  AudioFocus  requestAudioFocus() from uid/pid 10028/4004 clientId=android.media.AudioManager@9bfc5c1 req=3 flags=0x0
05-07 11:17:34.425  3609  3609 D NuPlayerDriver: start(0xb5dab080), state is 4, eos is 0
05-07 11:17:34.425  3609 19081 D NuPlayerDriver: stop(0xb5dab080)
05-07 11:17:34.425  3609 19081 D NuPlayerDriver: notifyListener_l(0xb5dab080), (8, 0, 0), loop setting(0, 0)
05-07 11:17:34.425  3609  3730 I GenericSource: start
05-07 11:17:34.444  3609  3730 W Utils   : track of type 'audio/vorbis' does not publish channel mask, channel count 2
05-07 11:17:34.446  4004  3729 W MediaPlayer: mediaplayer went away with unhandled events
05-07 11:17:34.447  3609 10145 D NuPlayerDriver: reset(0xb5dab080) at state 8
05-07 11:17:34.447  3609  3730 W Utils   : track of type 'audio/vorbis' does not publish channel mask, channel count 2
05-07 11:17:34.450  4951  3721 I Exchange: PSS syncEnd for account acct:17
05-07 11:17:34.450  3609  3735 I MediaPlayerService: MediaPlayerService::getOMX
05-07 11:17:34.450  4951  3721 I Exchange: PSS Signalling a pending sync to proceed acct:17.
05-07 11:17:34.452  3609  3735 I OMXClient: MuxOMX ctor
05-07 11:17:34.453  3606  4067 I OMXMaster: makeComponentInstance(OMX.google.vorbis.decoder) in mediacodec process
05-07 11:17:34.460  3606 19087 E OMXNodeInstance: setConfig(e16004c:google.vorbis.decoder, ConfigPriority(0x6f800002)) ERROR: Undefined(0x80001001)
05-07 11:17:34.461  3609  3735 I ACodec  : codec does not support config priority (err -2147483648)
05-07 11:17:34.463  3609  3735 I MediaCodec: MediaCodec will operate in async mode
05-07 11:17:34.481  4004  4021 I art     : Background partial concurrent mark sweep GC freed 73881(2MB) AllocSpace objects, 1(40KB) LOS objects, 39% free, 10MB/17MB, paused 2.427ms total 115.442ms
05-07 11:17:34.483  3609  3730 W AMessage: failed to post message as target looper for handler 0 is gone.
05-07 11:17:34.486  3609  3730 D NuPlayerDriver: notifyResetComplete(0xb5dab080)
05-07 11:17:34.488  3870  4636 I MediaFocusControl:  AudioFocus  abandonAudioFocus() from uid/pid 10028/4004 clientId=android.media.AudioManager@9bfc5c1
05-07 11:17:34.663  4951  3720 I Exchange: PSS syncEnd for account acct:17
05-07 11:17:34.663  4951  3720 I Exchange: PSS last sync succeeded, starting new ping acct:17.
05-07 11:17:34.666  4951  3738 I Exchange: Ping task starting for 17
05-07 11:17:34.683  4951  3738 I Exchange: Stop next with reason 1
05-07 11:17:34.683  4951  3738 I Exchange: Ping task ending with status: -1
05-07 11:17:34.684  4951  3738 I Exchange: PSS pingEnd for account 17
05-07 11:17:34.684  4951  3738 I Exchange: PSS pingEnd, starting new ping acct:17.
05-07 11:17:34.687  4951  3738 I Exchange: requestPing EasOperation Account {name=test.user@example.com, type=com.android.exchange}, Bundle[{force=true, __push_only__=true}]
05-07 11:17:34.837  4951  3739 I Exchange: onPerformSync email: Bundle[{ignore_settings=true, force=true, ignore_backoff=true, __push_only__=true}]
05-07 11:17:34.856  4951  3739 I Exchange: PSS pushStop acct:17
05-07 11:17:34.856  4951  3739 I Exchange: PSS pushStop acct:17
05-07 11:17:36.337 29741 29765 I NotifUtils: resendNotifications cancelExisting: false, account: null, folder: null
05-07 11:17:36.339 29741 29765 I NotifUtils: Validating Notification, mapSize: 1 getAttention: true ignoreUnobtrusive: false
05-07 11:17:36.379 29741 29765 I NotifUtils: Unseen count doesn't match cursor count.  unseen: 1 cursor count: 0
05-07 11:17:36.379 29741 29765 I NotifUtils: validateNotifications - cancelling account 55125872 / folder -608682334

      I hope that’s not too verbose.

      Thank you for any insight you can provide …

      1 Reply Last reply Reply Quote 0
      • Manfred
        Manfred Kopano last edited by

        Hi jsda,

        I’m not an android expert, but I’d say that “StrictMode: StrictMode policy violation; ~duration=1 ms: android.os.StrictMode$StrictModeDiskWriteViolation: policy=65543 violation=1” is the problem. I have no idea what’s causing or could cause this. Lack of permissions? No free space available? Some app which also access emails?

        You’ve edited the log after I started responding, so now the problems seems to be here:

        05-07 11:17:34.280 29741  3725 E NotifUtils: null from string in getWrappedFromString
05-07 11:17:34.281 29741  3725 E NotifUtils: Failed to load message
...
05-07 11:17:34.394 29741  3725 I NotifUtils: Unseen count doesn't match cursor count.  unseen: 1 cursor count: 0
05-07 11:17:34.394 29741  3725 I NotifUtils: validateNotifications - cancelling account 55125872 / folder -608682334

        It’s not clear what is going wrong here, at least not for me. Maybe you’d get better answers at android or samsung forums.

        Please also post the WBXML log of sending the email and syncing it to the mobile.

        Manfred

        1 Reply Last reply Reply Quote 0
        • jsda
          jsda last edited by

          Apologies for editing the log, I thought the receive email part would be more relevant and wasn’t expecting your quick attention (but glad to have it!)

          I don’t think free space is the issue, there is plenty on the device. There are no other web apps. I don’t think it is Samsung specific, as I have the same issue on an HTC Android 4.4.4 device too, but haven’t debugged that in a while. Both devices work with zarafa/z-push 2.1.3. Both devices are encrypted, maybe that’s a clue.

          I sent another email to the device, the output is below. I sanitized domain names and ip addresses. On the device, emails have disappeared from the inbox, and it is stuck at ‘getting your messages’. I have found the only way out of this condition is to toggle autosync or the network connection, after that I normally see all messages for a while, until they disappear on the next sync.

          The WBXML log exceeds the post limit on this forum. I’ll post it in parts. Sorry if that is a pain, happy to do this another way if that’s better.

          07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('INBOX') = b781a510
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->ChangesSink(): ChangesSink detected!!
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] ASDevice->GetFolderIdForBackendId(): this is a profile without backend-folderid mapping. Returning folderids as is.
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] ASDevice->GetFolderIdForBackendId(): no valid condition found for determining folderid for backendid 'b781a510'. Returning as is!
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] LoopDetection->IsSyncStateObsolete(): check folderid: 'b781a510' uuid '054192f1-0d27-41b2-b2c9-c71381202996' counter: 3 - last counter: 2 with 1 queued
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'b781a510', returning as is.
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '2' messages in state
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessageList('b781a510','1525117056')
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessageList(): searching with sequence '1,2,3'
07/05/2018 12:37:36 [ 5092] [ INFO] [test.user] ExportChangesDiff->InitializeExporter(): Found '1' changes for 'b781a510'
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] SyncCollections->CheckForChanges(): Notification received on folder 'b781a510'
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O  <Ping:Ping>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O   <Ping:Status>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O   2
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O   </Ping:Status>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O   <Ping:Folders>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O    <Ping:Folder>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O    b781a510
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O    </Ping:Folder>
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionAddStatus: 'b781a510' with status 2
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O   </Ping:Folders>
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] O  </Ping:Ping>
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] WBXMLEncoder->endTag() WBXML output completed
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] WBXML-OUT: AwFqAAANRUcDMgABSUoDYjc4MWE1MTAAAQEB
07/05/2018 12:37:36 [ 5092] [WBXML] [test.user] WBXML-IN : AwFqAAANRUgDNDgwAAFJSksDYjc4MWE1MTAAAUwDRW1haWwAAQFKSwNkMjNhMDMzYwABTANFbWFpbAABAQEB
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 501 bytes on file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionTerminate()
07/05/2018 12:37:36 [ 5092] [ INFO] [test.user] cmd='Ping' memory='2.00 MiB/2.00 MiB' time='318.23s' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' idle='319s' version='2.4.1+0-0' method='POST' httpcode='200'
07/05/2018 12:37:36 [ 5092] [DEBUG] [test.user] -------- End
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] -------- Start
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] cmd='Sync' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' version='2.4.1+0-0' method='POST'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Used timezone 'America/Vancouver'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Request::ProcessHeaders() ASVersion: 14.0
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsProvisioning(0): true
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '947' bytes from file: '/var/lib/z-push/4/6/android1506920854664-devicedata'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ASDevice data loaded for user: 'test.user'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18.
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22.
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::HierarchyCommand(0): false
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] DeviceManager->ProvisioningRequired('234299697') saved device key '234299697': false
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] DeviceManager->getPolicyName(): determined policy name: 'default'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsAuthentication(0): true
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): Excluding Folders (trash|junk|archive)
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): User 'test.user' is authenticated on '{localhost:143/imap/notls/norsh}'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsPlainInput(0): false
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I  <Synchronize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I   <Folders>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I    <Folder>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <SyncKey>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      {054192f1-0d27-41b2-b2c9-c71381202996}3
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     </SyncKey>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <FolderId>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      b781a510
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     </FolderId>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '906' bytes from file: '/var/lib/z-push/4/6/android1506920854664-054192f1-0d27-41b2-b2c9-c71381202996-fd'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] SyncParameters->UseCPO('DEFAULT')
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] DeviceManager->GetBackendIdForFolderId(): no backend-folderid available for 'b781a510', returning as is.
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] SyncCollections->AddCollection(): Folder id 'b781a510' : ref. PolicyKey '234299697', ref. Lifetime '480', last sync at '1525721073'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] SyncCollections->AddCollection(): Updated reference PolicyKey '234299697', reference Lifetime '480', Last sync at '1525721073'
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <DeletesAsMoves>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      1
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     </DeletesAsMoves>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <GetChanges/>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <WindowSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      10
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     </WindowSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     <Options>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      <FilterType>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] SyncParameters->UseCPO('DEFAULT')
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I       3
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      </FilterType>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      <AirSyncBase:BodyPreference>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I       <AirSyncBase:Type>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I        2
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I       </AirSyncBase:Type>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I       <AirSyncBase:TruncationSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I        204800
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I       </AirSyncBase:TruncationSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I      </AirSyncBase:BodyPreference>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I     </Options>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I    </Folder>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I   </Folders>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] I  </Synchronize>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] HandleSync(): Start Output
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Sync->loadStates(): loading states for folder 'b781a510'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->CleanStates(): Deleting file: '/var/lib/z-push/4/6/android1506920854664-054192f1-0d27-41b2-b2c9-c71381202996-2'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '160' bytes from file: '/var/lib/z-push/4/6/android1506920854664-054192f1-0d27-41b2-b2c9-c71381202996-3'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::GetAdditionalSyncFolderStore('b781a510'): 'false'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ZPush::GetAdditionalSyncFolderStore('b781a510'): 'false'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] ExportChangesDiff->InitializeExporter(): Initializing message diff engine. '2' messages in state
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessageList('b781a510','1525117057')
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '501' bytes from file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessageList(): searching with sequence '1,2,3'
07/05/2018 12:37:37 [ 5092] [ INFO] [test.user] ExportChangesDiff->InitializeExporter(): Found '1' changes for 'b781a510'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionAddStatus: 'b781a510' with status 1
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Folder type: Email
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O  <Synchronize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O   <Folders>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O    <Folder>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     <SyncKey>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     {054192f1-0d27-41b2-b2c9-c71381202996}4
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     </SyncKey>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     <FolderId>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     b781a510
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     </FolderId>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     <Status>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     1
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     </Status>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection->Detect(): folderid:'b781a510' uuid:'054192f1-0d27-41b2-b2c9-c71381202996' counter:'3' max:'10' queued:'1'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection->Detect(): case 1.2 detected
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection->Detect(): case 1.2.2 detected
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->StatMessage('b781a510','3')
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessage('b781a510', '3', '2')
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->StatMessage('b781a510','3')
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Utils::getRawMailHeaders(): subject = test 2
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] Utils::getRawMailHeaders(): from = =?utf-8?Q?XXXX_XXXX?= <xxxxx@xxxxx.com>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessage(): Message is multipart: 1, smime: 0, smime encrypted: 0
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessage(): getBodyPreferenceBestMatch: 2
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->GetMessage(): after thinking a bit we will use: 2
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] StringStreamWrapper::stream_open(): initialized stream length: 535 - HTML-safe-truncate: true
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     <Perform>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O      <Add>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O       <ServerEntryId>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O       3
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O       </ServerEntryId>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O       <Data>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:To>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        "Test User" <test.user@example.com>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:To>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:From>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        XXXXXX <xxxxx@xxxxx.com>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:From>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:Subject>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        test 2
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:Subject>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:ThreadTopic>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        test 2
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:ThreadTopic>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:DateReceived>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        2018-05-07T19:37:05.000Z
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:DateReceived>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:DisplayTo>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        "Test User"
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:DisplayTo>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:Importance>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        1
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:Importance>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:Read>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        0
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:Read>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:MessageClass>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        IPM.Note
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:MessageClass>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:InternetCPID>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        65001
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:InternetCPID>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <AirSyncBase:Body>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <AirSyncBase:Type>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         2
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         </AirSyncBase:Type>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <AirSyncBase:EstimatedDataSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         535
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         </AirSyncBase:EstimatedDataSize>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <AirSyncBase:Truncated>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         0
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         </AirSyncBase:Truncated>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <AirSyncBase:Data>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <<< written 535 of 535 bytes of plain data >>>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         </AirSyncBase:Data>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </AirSyncBase:Body>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:ContentClass>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        urn:content-classes:message
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:ContentClass>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <POOMMAIL:Flag>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         <POOMMAIL:FlagStatus>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         0
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O         </POOMMAIL:FlagStatus>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </POOMMAIL:Flag>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        <AirSyncBase:NativeBodyType>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        2
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O        </AirSyncBase:NativeBodyType>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O       </Data>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O      </Add>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O     </Perform>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O    </Folder>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 237 bytes on file: '/var/lib/z-push/4/6/android1506920854664-054192f1-0d27-41b2-b2c9-c71381202996-4'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] SyncCollections->SaveCollection(): Data of folder 'b781a510' changed
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 932 bytes on file: '/var/lib/z-push/4/6/android1506920854664-054192f1-0d27-41b2-b2c9-c71381202996-fd'
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O   </Folders>
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] O  </Synchronize>
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] WBXMLEncoder->endTag() WBXML output completed
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] WBXML-OUT: AwFqAEVcT0sDezA1NDE5MmYxLTBkMjctNDFiMi1iMmM5LWM3MTM4MTIwMjk5Nn00AAFSA2I3ODFhNTEwAAFOAzEAAVZHTQMzAAFdAAJWAyJUZXN0IFVzZXIiIDx0ZXN0LnVzZXJAY2FudWNrdGVjaC5jYT4AAVgDSmFzb24gU2hpZWxkcyA8amFzb25AY2FudWNrdGVjaC5jb20+AAFUA3Rlc3QgMgABdQN0ZXN0IDIAAU8DMjAxOC0wNS0wN1QxOTozNzowNS4wMDBaAAFRAyJUZXN0IFVzZXIiAAFSAzEAAVUDMAABUwNJUE0uTm90ZQABeQM2NTAwMQABABFKRgMyAAFMAzUzNQABTQMwAAFLAzwhRE9DVFlQRSBIVE1MIFBVQkxJQyAiLS8vVzNDLy9EVEQgSFRNTCA0LjAxIFRyYW5zaXRpb25hbC8vRU4iICJodHRwOi8vd3d3LnczLm9yZy9UUi9odG1sNC9sb29zZS5kdGQiPjxodG1sPg0KPGhlYWQ+DQogIDxtZXRhIG5hbWU9IkdlbmVyYXRvciIgY29udGVudD0iWmFyYWZhIFdlYkFwcCB2Ny4xLjExLTQ2MDUwIj4NCiAgPG1ldGEgaHR0cC1lcXVpdj0iQ29udGVudC1UeXBlIiBjb250ZW50PSJ0ZXh0L2h0bWw7IGNoYXJzZXQ9dXRmLTgiPg0KICA8dGl0bGU+dGVzdCAyPC90aXRsZT4NCjwvaGVhZD4NCjxib2R5Pg0KPHAgc3R5bGU9InBhZGRpbmc6IDA7IG1hcmdpbjogMDsiPjxzcGFuIHN0eWxlPSJmb250LWZhbWlseTogdGFob21hOyBmb250LXNpemU6IDEwcHQ7Ij5mb3IgbWFuZnJlZDxiciAvPjwvc3Bhbj48L3A+DQo8cCBzdHlsZT0icGFkZGluZzogMDsgbWFyZ2luOiAwOyI+PHNwYW4gc3R5bGU9ImZvbnQtZmFtaWx5OiB0YWhvbWE7IGZvbnQtc2l6ZTogMTBwdDsiPjxiciAvPjwvc3Bhbj48L3A+DQo8L2JvZHk+DQo8L2h0bWw+DQoAAQEAAnwDdXJuOmNvbnRlbnQtY2xhc3NlczptZXNzYWdlAAF6ewMwAAEBABFWAzIAAQEBAQEBAQ==
07/05/2018 12:37:37 [ 5092] [WBXML] [test.user] WBXML-IN : AwFqAEVcT0sDezA1NDE5MmYxLTBkMjctNDFiMi1iMmM5LWM3MTM4MTIwMjk5Nn0zAAFSA2I3ODFhNTEwAAFeAzEAARNVAzEwAAFXWAMzAAEAEUVGAzIAAUcDMjA0ODAwAAEBAQEBAQ==
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 501 bytes on file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionTerminate()
07/05/2018 12:37:37 [ 5092] [ INFO] [test.user] cmd='Sync' memory='2.06 MiB/2.00 MiB' time='0.03s' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' idle='0s' version='2.4.1+0-0' method='POST' httpcode='200'
07/05/2018 12:37:37 [ 5092] [DEBUG] [test.user] -------- End
          1 Reply Last reply Reply Quote 0
          • jsda
            jsda last edited by

            log, continued

            07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] -------- Start
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] cmd='FolderSync' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' version='2.4.1+0-0' method='POST'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Used timezone 'America/Vancouver'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Request::ProcessHeaders() ASVersion: 14.0
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsProvisioning(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '947' bytes from file: '/var/lib/z-push/4/6/android1506920854664-devicedata'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice data loaded for user: 'test.user'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::HierarchyCommand(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->ProvisioningRequired('234299697') saved device key '234299697': false
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->getPolicyName(): determined policy name: 'default'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsAuthentication(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): Excluding Folders (trash|junk|archive)
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): User 'test.user' is authenticated on '{localhost:143/imap/notls/norsh}'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsPlainInput(9): false
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I  <FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I   <FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I    {3b5a2f76-92fd-4e72-9f86-893551cf63d2}1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I   </FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] StateManager->loadHierarchyCache(): 'android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-hc-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '755' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-hc-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '314' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-fd'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] SyncParameters->UseCPO('DEFAULT')
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 4
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I  </FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 1
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '501' bytes from file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('INBOX') = b781a510
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('INBOX') = b781a510
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Saved') = 85643c69
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Saved') = 85643c69
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Pattern: <junk> found, excluding folder: '{localhost:143/imap/notls/norsh}Junk'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Drafts') = 359e3148
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Drafts') = 359e3148
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Sent') = d23a033c
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Sent') = d23a033c
07/05/2018 12:37:38 [ 5092] [ INFO] [test.user] ExportChangesDiff->InitializeExporter(): Found '4' changes for 'hierarchy'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('b781a510'): 'SyncFolder (
	(S) serverid => b781a510
	(S) parentid => 0
	(S) displayname => Inbox
	(S) type => 2
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('b781a510'): 'SyncFolder (
	(S) serverid => b781a510
	(S) parentid => 0
	(S) displayname => Inbox
	(S) type => 2
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('85643c69') = Saved
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('85643c69'): 'SyncFolder (
	(S) serverid => 85643c69
	(S) parentid => 0
	(S) displayname => Saved
	(S) type => 12
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('85643c69') = Saved
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('85643c69'): 'SyncFolder (
	(S) serverid => 85643c69
	(S) parentid => 0
	(S) displayname => Saved
	(S) type => 12
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Saved' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('359e3148') = Drafts
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('359e3148'): 'SyncFolder (
	(S) serverid => 359e3148
	(S) parentid => 0
	(S) displayname => Drafts
	(S) type => 3
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('359e3148') = Drafts
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('359e3148'): 'SyncFolder (
	(S) serverid => 359e3148
	(S) parentid => 0
	(S) displayname => Drafts
	(S) type => 3
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('d23a033c') = Sent
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('d23a033c'): 'SyncFolder (
	(S) serverid => d23a033c
	(S) parentid => 0
	(S) displayname => Sent
	(S) type => 5
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('d23a033c') = Sent
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('d23a033c'): 'SyncFolder (
	(S) serverid => d23a033c
	(S) parentid => 0
	(S) displayname => Sent
	(S) type => 5
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O  <FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:Status>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:Status>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   {3b5a2f76-92fd-4e72-9f86-893551cf63d2}1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:Changes>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    <FolderHierarchy:Count>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    0
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    </FolderHierarchy:Count>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:Changes>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 4
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O  </FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] WBXMLEncoder->endTag() WBXML output completed
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] WBXML-OUT: AwFqAAAHVkwDMQABUgN7M2I1YTJmNzYtOTJmZC00ZTcyLTlmODYtODkzNTUxY2Y2M2QyfTEAAU5XAzAAAQEB
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] WBXML-IN : AwFqAAAHVlIDezNiNWEyZjc2LTkyZmQtNGU3Mi05Zjg2LTg5MzU1MWNmNjNkMn0xAAEB
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 501 bytes on file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionTerminate()
07/05/2018 12:37:38 [ 5092] [ INFO] [test.user] cmd='FolderSync' memory='1.91 MiB/2.00 MiB' time='0.03s' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' idle='0s' version='2.4.1+0-0' method='POST' httpcode='200'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] -------- End
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] -------- Start
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] cmd='FolderSync' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' version='2.4.1+0-0' method='POST'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Used timezone 'America/Vancouver'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Request::ProcessHeaders() ASVersion: 14.0
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsProvisioning(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '947' bytes from file: '/var/lib/z-push/4/6/android1506920854664-devicedata'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice data loaded for user: 'test.user'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::HierarchyCommand(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->ProvisioningRequired('234299697') saved device key '234299697': false
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->getPolicyName(): determined policy name: 'default'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->getProvisioningPolicies(): loaded 'default' policy.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsAuthentication(9): true
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): Excluding Folders (trash|junk|archive)
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->Logon(): User 'test.user' is authenticated on '{localhost:143/imap/notls/norsh}'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ZPush::CommandNeedsPlainInput(9): false
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I  <FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I   <FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I    {3b5a2f76-92fd-4e72-9f86-893551cf63d2}1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I   </FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] StateManager->loadHierarchyCache(): 'android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-hc-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '755' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-hc-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '314' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-1'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '379' bytes from file: '/var/lib/z-push/4/6/android1506920854664-3b5a2f76-92fd-4e72-9f86-893551cf63d2-fd'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] SyncParameters->UseCPO('DEFAULT')
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 4
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] I  </FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 1
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->GetState() read '501' bytes from file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('INBOX') = b781a510
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('INBOX') = b781a510
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Saved') = 85643c69
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Saved') = 85643c69
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] Pattern: <junk> found, excluding folder: '{localhost:143/imap/notls/norsh}Junk'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Drafts') = 359e3148
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Drafts') = 359e3148
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getFolderIdFromImapId('Sent') = d23a033c
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->convertImapId('Sent') = d23a033c
07/05/2018 12:37:38 [ 5092] [ INFO] [test.user] ExportChangesDiff->InitializeExporter(): Found '4' changes for 'hierarchy'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('b781a510'): 'SyncFolder (
	(S) serverid => b781a510
	(S) parentid => 0
	(S) displayname => Inbox
	(S) type => 2
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('b781a510') = INBOX
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('b781a510'): 'SyncFolder (
	(S) serverid => b781a510
	(S) parentid => 0
	(S) displayname => Inbox
	(S) type => 2
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Inbox' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('85643c69') = Saved
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('85643c69'): 'SyncFolder (
	(S) serverid => 85643c69
	(S) parentid => 0
	(S) displayname => Saved
	(S) type => 12
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('85643c69') = Saved
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('85643c69'): 'SyncFolder (
	(S) serverid => 85643c69
	(S) parentid => 0
	(S) displayname => Saved
	(S) type => 12
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Saved' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('359e3148') = Drafts
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('359e3148'): 'SyncFolder (
	(S) serverid => 359e3148
	(S) parentid => 0
	(S) displayname => Drafts
	(S) type => 3
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('359e3148') = Drafts
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('359e3148'): 'SyncFolder (
	(S) serverid => 359e3148
	(S) parentid => 0
	(S) displayname => Drafts
	(S) type => 3
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Drafts' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('d23a033c') = Sent
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('d23a033c'): 'SyncFolder (
	(S) serverid => d23a033c
	(S) parentid => 0
	(S) displayname => Sent
	(S) type => 5
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('d23a033c') = Sent
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->GetFolder('d23a033c'): 'SyncFolder (
	(S) serverid => d23a033c
	(S) parentid => 0
	(S) displayname => Sent
	(S) type => 5
	(S) Store => null
	(S) NoBackendFolder => null
	(S) BackendId => null
	(S) Flags => null
	(S) TypeReal => null
	unsetVars(Array) size: 0
	supportsPrivateStripping => false
	flags => false
	content => null
)'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant.
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O  <FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:Status>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:Status>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   {3b5a2f76-92fd-4e72-9f86-893551cf63d2}1
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:SyncKey>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   <FolderHierarchy:Changes>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    <FolderHierarchy:Count>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    0
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O    </FolderHierarchy:Count>
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O   </FolderHierarchy:Changes>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] DeviceManager->CheckFolderData() checking integrity of hierarchy cache with synchronized folders
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 4
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] O  </FolderHierarchy:FolderSync>
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] WBXMLEncoder->endTag() WBXML output completed
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] WBXML-OUT: AwFqAAAHVkwDMQABUgN7M2I1YTJmNzYtOTJmZC00ZTcyLTlmODYtODkzNTUxY2Y2M2QyfTEAAU5XAzAAAQEB
07/05/2018 12:37:38 [ 5092] [WBXML] [test.user] WBXML-IN : AwFqAAAHVlIDezNiNWEyZjc2LTkyZmQtNGU3Mi05Zjg2LTg5MzU1MWNmNjNkMn0xAAEB
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] FileStateMachine->SetState() written 501 bytes on file: '/var/lib/z-push/4/6/android1506920854664-bs-1525715479'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionTerminate()
07/05/2018 12:37:38 [ 5092] [ INFO] [test.user] cmd='FolderSync' memory='1.91 MiB/2.00 MiB' time='0.02s' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx' idle='0s' version='2.4.1+0-0' method='POST' httpcode='200'
07/05/2018 12:37:38 [ 5092] [DEBUG] [test.user] -------- End
            1 Reply Last reply Reply Quote 0
            • Manfred
              Manfred Kopano last edited by

              Hi jsda,

              you can also upload the logs somewhere and send me the link. Anyway, it looks like Z-Push - IMAP connection isn’t an issue as there are emails being synced to the devices.
              As the problem is not a vendor specific, it might be some android issue. Maybe the device encryption as you mentioned it.

              You could try to let the backend return different AS versions. In the GetSupportedASVersion() function of the imap.php (around the line 1800), e.g. ZPush::ASV_12 or ZPush::ASV_121 or ZPush::ASV_141. Maybe the devices do something differently depending on the ActiveSync Version Z-Push sends. If you try this, just make sure in the log you see the version you set in imap.php, e.g.:
              Request::ProcessHeaders() ASVersion: 14.0
              (you might need to force the complete resync in order this change to take effect).

              Manfred

              1 Reply Last reply Reply Quote 0
              • Enrice
                Enrice last edited by

                Same here. z-push 2.1.x has been working well, I have reinstalled my box with Ubuntu 18.04 with included 2.3.8, also tried current 2.4.3, to no avail. synchronization loops with default android email app and almost any other free one.

                My backend is plain (courier-)imap with apache.
                I tried to reduce email age to 1 day. sync loops only happen more often…
                debug logging showed nothing special - only warnings about missing combined.php from combined backend.

                Windows mail is working like a charm. on my mobile, the only working app was “nine”, which may have their own AS implementation, not relying on the OS one.

                Manfred 1 Reply Last reply Reply Quote 0
                • Manfred
                  Manfred Kopano @Enrice last edited by

                  Hi Enrice,

                  without Z-Push logs it’s not possible to tell for sure what’s going on. If you post them, I’ll take a look,

                  @enrice said in Sync problem with default Android application:

                  My backend is plain (courier-)imap with apache.
                  I tried to reduce email age to 1 day. sync loops only happen more often…
                  debug logging showed nothing special - only warnings about missing combined.php from combined backend.

                  What is the value of BACKEND_PROVIDER in z-push.conf.php?

                  Manfred

                  1 Reply Last reply Reply Quote 0
                  • Enrice
                    Enrice last edited by

                    it is actually empty. the backend is autodiscovered, isn’t it?

                    Manfred 1 Reply Last reply Reply Quote 0
                    • Manfred
                      Manfred Kopano @Enrice last edited by

                      Hi Enrice,

                      @enrice said in Sync problem with default Android application:

                      it is actually empty. the backend is autodiscovered, isn’t it?

                      Yes, but Z-Push tries to load combined before imap, that’s why you see the warnings about missing backend.

                      Manfred

                      1 Reply Last reply Reply Quote 0
                      • Enrice
                        Enrice last edited by

                        logs sent via PM

                        1 Reply Last reply Reply Quote 0
                        • Manfred
                          Manfred Kopano last edited by

                          Hi Enrice,

                          the folder list looks not sorted (e.g. INBOX.Drafts folder is before Inbox) and so some folders aren’t being sent to the mobile. There are several log entries like this:

                          Change for folder 'Drafts' will not be sent as parent folder is not set or not known on mobile.

                          But then Z-Push detects that there are unsynced folders and the whole folder sync begins again.

                          What was your update procedure? Or did you install Z-Push from scratch and started syncing from 0? Did you migrate the states?

                          Manfred

                          1 Reply Last reply Reply Quote 0
                          • Enrice
                            Enrice last edited by

                            yes, I installed from scratch, actually the version that came with ubuntu 18.4 LTS, which was 2.3.something. I did not migrate anything.

                            Manfred 1 Reply Last reply Reply Quote 0
                            • jsda
                              jsda last edited by

                              I still can’t get z-push to work on any android device. Over the last few weeks I have:

                              • Changed the AS version in the GetSupportedASVersion() function of the imap.php. I tried ZPush::ASV_12 or ZPush::ASV_121 or ZPush::ASV_141 but no improvement
                              • Removed android encryption, reformatting data partition, no change
                              • Tried various devices, Android stock roms and LineageOS, none work
                              • Tried installing Z-Push from ‘final’ and ‘old-final’ repositories, no change

                              Bottom line is Z-Push does not work on any android device, mail app or any combination I can find. The symptoms are a bit different in each case, but none work:

                              • Using LineageOS Android 7.1.2, mail syncs, but then flashes and disappears as described above.
                              • With Android 4.4.4 default mail app, the mail synchronizes and does not disappear, but message body is blank and emails sent from the device arrive without any message body
                              • With Android 7.0 with Samsung mail app - configuration seems to succeed but no mail is visible on the device at all

                              Again, all these devices and Android versions synchronize perfectly with Z-Push 2.1.3 / Zarafa.

                              It might be important to note that the same flashing / disappearing happens to contacts and calendar items with LineageOS Android 7.1.2, not just IMAP mail. So this issue doesn’t seem to be particularly related to the IMAP backend.

                              My software versions for reference:

                              Ubuntu 16.04
                              Apache 2.4.18
                              PHP 7.0.28
                              Dovecot 2.2.22
                              Z-Push 2.3.9+0-0

                              I am completely at wits end over this. My gut says maybe the issue is with the Apache configuration, character encoding or something like that.

                              At this point I would be willing to try just about anything to get this issue resolved. Does anyone have any suggestions? Manfred?

                              1 Reply Last reply Reply Quote 0
                              • Manfred
                                Manfred Kopano @Enrice last edited by

                                Hi enrice ,

                                @enrice said in Sync problem with default Android application:

                                yes, I installed from scratch, actually the version that came with ubuntu 18.4 LTS, which was 2.3.something. I did not migrate anything.

                                Did you try adding z-push repositories as described at https://wiki.z-hub.io/display/ZP/Installation? Did you make any changes to the imap backend config file?

                                Manfred

                                Enrice 1 Reply Last reply Reply Quote 0
                                • Manfred
                                  Manfred Kopano last edited by

                                  Hi @jsda

                                  Z-Push 2.3.X has been deprecated. Current Z-Push stable is 2.4.4. It’s been a while since your last post, so providing Z-Push logs might give some better insight.

                                  Manfred

                                  1 Reply Last reply Reply Quote 0
                                  • liverpoolfcfan
                                    liverpoolfcfan last edited by

                                    Have you allowed for long enough sessions on your web server/firewall? Remember an active PING from a device to the server can last just shy of 1 hour. That is way more than a normal web server is configured for. Also, an active session, gathering emails can take longer than is typically allowed before the first byte is returned to the client.

                                    A good suggestion when debugging an issue like this is to reduce this in the main config file
                                    define(‘SYNC_MAX_ITEMS’, 512);

                                    to something like 128

                                    1 Reply Last reply Reply Quote 0
                                    • jsda
                                      jsda last edited by

                                      Thank you Manfred for your continued attention to this issue.

                                      I have rolled back my test server for a fresh start and installed z-push from repos and confirm it is now v2.4.4.

                                      I also changed SYNC_MAX_ITEMS to 128 as liverpoolfcfan suggested, although since my test inbox never has more than a handful of emails, I’m guessing that makes no difference. But I do suspect some kind of timeout in the webserver or z-push configuration as being the root of this issue, just a hunch.

                                      My test mailbox has just 1 unread message when I configure the default Android mail app in LineageOS.

                                      Unfortunately I see the same behavior as before: The first synchronization seems to stall, but toggling the sync icon on the device restarts the syncronization and the inbox is synced. Then after sending a new message to the test inbox, synchronization seems to stall again. Toggling the sync icon restarts it, and all messages appear in the inbox. But then one or more will disappear, usually after viewing a message, or doing a manual refresh of the inbox.

                                      I have WBXML logs for all this, but they are way too verbose to post here. I can clip sections if you tell me what to include.

                                      FYI, I noticed each line in the log displays “… [DEBUG] [#unknown] …” where on earlier z-push versions it includes the username “… [DEBUG] [test.user] …”, not sure if that might be related to this issue or not.

                                      Also, I noticed the apache configuration file at /etc/apache2/conf-available/z-push.conf does not include some of the directives seen in 2.3.x, and am wondering if that is intentional or maybe an oversight.

                                      php_value magic_quotes_gpc off
php_value magic_quotes_runtime off
php_value register_globals off
php_value short_open_tag on

                                      Thanks again for helping.

                                      1 Reply Last reply Reply Quote 0
                                      • Manfred
                                        Manfred Kopano last edited by

                                        Hi jsda,

                                        you can upload the log somewhere and send me the link per PN. I’m not able to tell what to include as I don’t know what’s in the logs.

                                        We removed those php_value settings to support fpm in webserver config: https://jira.z-hub.io/browse/ZP-1145.

                                        Manfred

                                        1 Reply Last reply Reply Quote 0
                                        • jsda
                                          jsda last edited by

                                          Hi Manfred, I have sent an external link via this site’s chat function, not sure if that is what you meant by ‘PN’. If there is another way to send a direct message, I can’t find it. Thanks.

                                          1 Reply Last reply Reply Quote 0
                                          • Manfred
                                            Manfred Kopano last edited by

                                            Hi jsda,

                                            yes, by “PN” I meant chat. I’ve downloaded the logs in case you want to remove them from the download site.

                                            It has probably nothing to do with your issue, but did you update the Z-Push config? There are quite some log entries like:

                                            The configuration parameter 'USE_X_FORWARDED_FOR_HEADER' was deprecated in favor of 'USE_CUSTOM_REMOTE_IP_HEADER'. Please update your configuration.

                                            You have to replace USE_X_FORWARDED_FOR_HEADER with USE_CUSTOM_REMOTE_IP_HEADER.

                                            I don’t see anything obviously wrong in the log, only a couple of strange things.

                                            The device performs FolderSync quite often which is not usual (it might be due to the fact that you forced sync though).

                                            Are there really only 4 folders? Isn’t there deleted items or wastebasket or similar folder? Isn’t there outbox folder? Please also post your imap.conf.php contents.

                                            Manfred

                                            1 Reply Last reply Reply Quote 0
                                            • First post
                                              Last post