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
    4638
    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.
    • lukasde
      lukasde last edited by fbartels

      Hello,

      I have problem with syncing emails in default application (Gmail) in Android 6 and Android 7 (but for example in Nine or Mailwise all works goodly).

      I don’t see all emails, or I see empty inbox, or my gmail is freezing up or it’s getting to loop during synchronization, or it freeze after switch from sent folder to inbox folder, etc.

      I think it’s problem with default folders (I set up it in imap.conf.php as you can see below, but without success).

      My configuration is:
      z-push with backendcombined with backends imap, carddav, caldav
      centos 6.5, dovecot 2.2.x (maildir), apache 2.4.x, php 5.6.x (I don’t use php-fpm)

      This is structure of my typical mailbox:

      drwx------ 5 test6 uzivatele 4096 Jun 28 14:51 Archive
drwxr-xr-x 2 test6 uzivatele 4096 Jun 28 15:05 cur
-rw-r--r-- 1 test6 uzivatele 0 Jun 28 14:58 dovecot-acl-list
-rw-r--r-- 1 test6 uzivatele 2464 Jun 29 15:09 dovecot.index.cache
-rw-r--r-- 1 test6 uzivatele 1988 Jun 28 15:05 dovecot.index.log
-rw-r--r-- 1 test6 uzivatele 154 Jun 28 15:04 dovecot-uidlist
-rw-r--r-- 1 test6 uzivatele 8 Jun 28 15:00 dovecot-uidvalidity
-r--r--r-- 1 test6 uzivatele 0 Jun 28 14:58 dovecot-uidvalidity.5953a7fb
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 Drafts
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 INBOX
drwxr-xr-x 2 test6 uzivatele 4096 Jun 28 15:04 new
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 saved-messages
drwx------ 5 test6 uzivatele 4096 Jun 29 14:27 Sent
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 sent-mail
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 Spam
drwxr-xr-x 2 test6 uzivatele 4096 Jun 28 15:04 tmp
drwx------ 5 test6 uzivatele 4096 Jun 28 14:50 Trash

      This is my imap.conf.php:

      define('IMAP_FOLDER_INBOX', 'INBOX');
// Sent folder name (case doesn't matter)
define('IMAP_FOLDER_SENT', 'Sent');

// Draft folder name (case doesn't matter)
define('IMAP_FOLDER_DRAFT', 'Drafts');

// Trash folder name (case doesn't matter)
define('IMAP_FOLDER_TRASH', 'Trash');

// Spam folder name (case doesn't matter). Only showed as special by iOS devices
define('IMAP_FOLDER_SPAM', 'Spam');

// Archive folder name (case doesn't matter). Only showed as special by iOS devices
define('IMAP_FOLDER_ARCHIVE', 'Archive');

      Here is my wbxml.log https://pastebin.com/TFHKaBRj

      Please do you have any idea?

      Thank you very much,
      Lukas

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

        I think only problem is with settings of IMAP_FOLDER_INBOX. Because now I always see new email only for few seconds and then it is disappearing. I tried set this value to “inbox” or “cur” or leave it empty, but without success. So I don’t know how to set it for this configuration of maildir

        Lukas

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

          I know I’ve seen similar before, where emails would appear, flash then disappear… sort of looping…

          However, looking back in your logs:

          29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCalDAV->Logon(): User 'test6' is authenticated on CalDAV 'http://groupware.xxx.cz:80/caldav.php/test6/'
29/06/2017 15:53:31 [23493] [DEBUG] [test6] BackendCardDAV->Logon(): User 'test6' is authenticated on 'http://groupware.xxx.cz:80/caldav.php/test6/'

          It looks like you’re using the same url for carddav and caldav?? I’m not sure if that could be affecting things, but I had a massive pain trying to get caldav working when the android gmail client introduced supported for “Tasks” I think, around that time, I saw a similar problem to you…

          Not seeing anything else out of the ordinary… though I will say you’ve folder duplications (Sent vs sent-mail, saved-messages versus Drafts)

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

            Hello,

            thank you for reply.

            It’s URL for logon, it’s same. But URL for resources is different, for example http://groupware.xxx.cz:80/caldav.php/test6/calendar, http://groupware.xxx.cz:80/caldav.php/test6/addresses, etc. I think it’s OK.

            Duplicate folders are from another emails clients, their removing doesn’t help.

            I alsou thought about Tasks, I tried turn off, but it also doesn’t help me:(

            >I know I’ve seen similar before, where emails would appear, flash then disappear… sort of looping…*
            Yes, I had exactly same problem. When I set IMAP folders as can you see above, so I have “only” problem, that I don’t see all emails in INBOX, or they are dissappearing, etc. I think that I should set IMAP_FOLDER_INBOX to empty value in my Maildir configuration, but it causes loop

            Lukas

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