Sync problem with default Android application

Manfred

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

jsda

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

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.