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

      Has anyone found a solution to this problem? My inbox mail also disappears in the way described by Lukas.

      Z-Push works perfectly with Outlook 2013, the problem only occurs in default mail app in Android 4.4.4 and Android 7.2.1.

      I can post wbxml logs as needed.

      Versions:
      Z-Push 2.4.1
      Dovecot 2.2.22

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

        Here is a bit more detail hoping someone can help.

        I am running:

        Ubuntu 16.04
        Apache 2.4.18
        PHP 7.0.28
        Dovecot 2.2.22

        Z-Push is installed via repositories. Current version is 2.4.1, have also tried 2.4 and 2.3.9 with the same result.

        Z-Push seems to work as expected except when using the default Android mail app. I have tested on Android 4.4.4 and Android 7.2.1. Both these devices work great with Z-Push 2.1.3 / Zarafa.

        I originally configured Z-Push with BackendCombined, but have switched to using just BackendIMAP to debug this issue.

        Initial mail configuration on Android works as expected, without any unusual delays or timeouts. Provisioning seems to succeed. However, after accepting Z-Push as a device administrator, the device appears to do nothing.

        The logs indicate a sync started, there are entries like this for each folder:

         05/05/2018 07:11:55 [10634] [DEBUG] [test.user] BackendIMAP->GetFolder('e8419eff'): 'SyncFolder (
    (S) serverid => e8419eff
    (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
 )'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] BackendIMAP->getImapIdFromFolderId('e8419eff') = INBOX
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] BackendIMAP->GetFolder('e8419eff'): 'SyncFolder (
     (S) serverid => e8419eff
     (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
 )'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] HierarchyCache: AddFolder() serverid: e8419eff displayname: Inbox

        There are similar logs for each folder, each repeated twice as above (not sure if that’s normal or not).

        Despite this, no mail appears on the device. Z-Push logs end with

         05/05/2018 07:11:55 [10634] [DEBUG] [test.user] StateManager::linkState(#ASDevice, 'aefdc5ee-c4e0-4df8-be03-7b2ade36cc6e','HierarchyCache'): linked to uuid 'aefdc5ee-c4e0-4df8-be03-7b2ade36cc6e'.
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 4
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SqlStateMachine->SetState(): devid:'android1506920854664' type:'hc' key:'aefdc5ee-c4e0-4df8-be03-7b2ade36cc6e' counter:'1'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SqlStateMachine->SetState(): devid:'android1506920854664' type:'' key:'aefdc5ee-c4e0-4df8-be03-7b2ade36cc6e' counter:'1'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SyncCollections::InvalidatePingableFlags(): Invalidating now
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SqlStateMachine->SetState(): devid:'android1506920854664' type:'fd' key:'aefdc5ee-c4e0-4df8-be03-7b2ade36cc6e' counter:'false'
 05/05/2018 07:11:55 [10634] [WBXML] [test.user] O  </FolderHierarchy:FolderSync>
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] WBXMLEncoder->endTag() WBXML output completed
 05/05/2018 07:11:55 [10634] [WBXML] [test.user] WBXML-OUT: AwFqAAAHVkwDMQABUgN7YWVmZGM1ZWUtYzRlMC00ZGY4LWJlMDMtN2IyYWRlMzZjYzZlfTEAAU5XAzQAAU9IA2U4NDE5ZWZmAAFJAzAAAUcDSW5ib3gAAUoDMgABAU9IA2NmZjMwNDQzAAFJAzAAAUcDU2VudAABSgM1AAEBT0gDZmUyYTFhN2UAAUkDMAABRwNTYXZlZAABSgMxMgABAU9IAzU5MzNlZTdlAAFJAzAAAUcDRHJhZnRzAAFKAzMAAQEBAQ==
 05/05/2018 07:11:55 [10634] [WBXML] [test.user] WBXML-IN : AwFqAAAHVlIDMAABAQ==
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] Special header: MS-ASProtocolVersions: 12.0,12.1,14.0
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] Special header: MS-ASProtocolCommands:      Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] BackendIMAP->close_connection(): disconnected from IMAP server
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SqlStateMachine->SetState(): devid:'android1506920854664' type:'bs' key:'null' counter:'1525529494'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] DeviceManager->Save(): Device data changed
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] SqlStateMachine->SetState(): devid:'android1506920854664' type:'devicedata' key:'null' counter:'false'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] DeviceManager->Save(): Device data saved
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] LoopDetection->ProcessLoopDetectionTerminate()
 05/05/2018 07:11:55 [10634] [ INFO] [test.user] cmd='FolderSync' memory='4.40 MiB/4.00 MiB' time='0.05s' devType='samsungSMP' devId='android1506920854664' getUser='test.user' from='xxx.xxx.xxx.xxx1' idle='0s' version='2.4.1+0-0' method='POST' httpcode='200'
 05/05/2018 07:11:55 [10634] [DEBUG] [test.user] -------- End

        Sync seems stuck at this point. Z-Push-Top shows no sync connections, no ping. I have tried waiting long periods of time, with no joy.

        From here the only way to move forward is to toggle device’s network or auto-synchronisation service. When I do this, the device starts synchronising. Mail appears in the inbox, then disappears, then appears again in rapid succession. I think always three times, until I finally see mail in my inbox.

        At this point all looks good on the device, but it is not. There is still no ping showing in Z-Push-Top. New mail is not pushed to the device. New mail arrives when I refresh the inbox, but then older messages disappear. The disappeared messages are still on the sever and are seen in IMAP clients and Outlook 2013 over ActiveSync.

        I can usually get missing messages to reappear by toggling Android’s autosync or network connection again, but then they always disappear later. Usually only the most recent message is displayed, sometimes none at all.

        This seems to only be a problem in the INBOX. Following lukasde’s line of thought, I have tried various Dovecot INBOX configurations, but unfortunately with the same results.

         #mail_location = maildir:/srv/data/vmail/%u
 #mail_location = maildir:/srv/data/vmail/%u:LAYOUT=fs
 #mail_location = maildir:/srv/data/vmail/%u/Maildir
 #mail_location = maildir:/srv/data/vmail/%u/Maildir:INBOX=/srv/data/vmail/%u/Maildir/.INBOX
 mail_location = maildir:/srv/data/vmail/%u/Maildir:INBOX=/srv/data/vmail/%u/Maildir/INBOX
 #mail_location = maildir:/srv/data/vmail/%u/Maildir:INBOX=/srv/data/vmail/%u/Maildir/INBOX:LAYOUT=fs
 #mail_location = maildir:/srv/data/vmail/%u:INBOX=/srv/data/vmail/%u/.INBOX
 #mail_location = maildir:/srv/data/vmail/%u:INBOX=/srv/data/vmail/%u/INBOX:LAYOUT=fs

        I tried using SQL state machine, but that made no difference.

        define('STATE_MACHINE', 'SQL');

        I tried enabling partial folder sync, no difference.

        define('USE_PARTIAL_FOLDERSYNC', true);

        I tried defining a short timeout for the device, no difference.

        define('SYNC_TIMEOUT_SHORT_DEVICETYPES', "samsungSMP");

        I have also disabled opcache in php.ini, no difference.

        opcache.enable=1
opcache.enable_cli=1

        I just can seem to get past this issue. Can anyone offer insight that might help move forward? I have used Z-Push for years and am so disappointed to be stuck on this. Something tells me a small configuration change would make the difference, but I have no idea what that might be. Anyone?

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

          Hi jsda,

          have you tried debugging the device with logcat?

          Please post the z-push-admin list output for that user.

          Manfred

          1 Reply Last reply Reply Quote 0
          • 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
                                            • First post
                                              Last post