Sync problem with default Android application

jsda

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

Manfred

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

Enrice

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

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

Enrice

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

Manfred

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

Enrice

logs sent via PM

Manfred

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

Enrice

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.

jsda

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?

Manfred

Hi enrice ,

@enrice said in Sync problem with default Android application:

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

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

Manfred

Manfred

Hi @jsda

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

Manfred

liverpoolfcfan

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

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

to something like 128

jsda

Thank you Manfred for your continued attention to this issue.

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

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

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

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

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

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

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

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

Thanks again for helping.

Manfred

Hi jsda,

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

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

Manfred

jsda

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

Manfred

Hi jsda,

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

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

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

You have to replace USE_X_FORWARDED_FOR_HEADER with USE_CUSTOM_REMOTE_IP_HEADER.

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

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

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

Manfred

Enrice

@manfred said in Sync problem with default Android application:

Hi enrice ,

@enrice said in Sync problem with default Android application:

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

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

Manfred

Hi.
yes, I added them to install the latest stable version. I will again provide you with current logs.
I also fiddled around with some config settings.

Enrice

I gave the PHP scripts 256M, that seemed to have fixed the issue.

Enrice

@Enrice said in Sync problem with default Android application:

I gave the PHP scripts 256M, that seemed to have fixed the issue.

hmm. not really. got better, but problem still remains…