Sync problem with default Android application
-
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 -
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
-
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)
-
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 loopLukas
-
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 -
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.22Z-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?
-
Hi jsda,
have you tried debugging the device with logcat?
Please post the z-push-admin list output for that user.
Manfred
-
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 …
-
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
-
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
-
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
-
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
-
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.
-
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
-
it is actually empty. the backend is autodiscovered, isn’t it?
-
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
-
logs sent via PM
-
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
-
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.
-
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-0I 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?