Timeout message when fetching mails - empty inbox
-
Hi,
I’m trying to use z-push for Android clients (Outlook App or the Gmail App). Currently, I disabled other backends except IMAP, to isolate the problem of sync->disappearance of data->sync cycle.
I found this message in the log02/04/2020 00:17:14 [114165] [ INFO] [feuerstein] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 174s from 470s due to other process - code: 3 - file: /appl/httpd/z-push/inst/lib/core/synccollections.php:579
Is anyone familiar with this problem? Is the problem with my config or is it with the IMAP server? The only other message I found in the log that looked relevant was
Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command
I could send Email though.
Thank you very much,
Elan -
@elan The timeout message just indicates that a second ping was started before the previous one ended. This can happen when individual folders are synced, and it should be expected once in a while. It should not be the norm though.
Typically when clients drop everything and resync it is because one or more needed folder is not syncing.
I am not familiar with the IMAP backend but, at a minimum, have you defined folders for Inbox, Outbox, Sent, and Trash. If any of them is missing this could be the problem.
-
@liverpoolfcfan , Thank you for the reply. The timeout with long wait periods seems to be happening all the time. The call to FoldersSync does not seem to return.
When I check with telnet, the IMAP seems to have INBOX/Sent, INBOX/Trash, INBOX/Drafts and INBOX. I configured these in the backend/imap/config.php.
The config file also IMAP_FOLDER_SPAM and IMAP_FOLDER_ARCHIVE. These I configured to be INBOX/SPAM and INBOX/ARCHIVE, assuming that the IMAP Server will create them when required. Still the same problem. I commented out these lines, didn’t make a difference.
Thanks for the input, I’ll look in this direction. I have z-push 2.5.1. Will also try with the latest update. -
Hi @elan,
is the issue that no emails are synced and all email folders are empty? Was the folder structure synced correctly to your mobile?
What exactly are Outlook App and Gmail App you’re referring to? Did you try to configure an ActiveSync account using the default email app using Settings->Accounts?
It would help more if you would post the complete WBXML level log of a Sync request.
Manfred
-
Hi @Manfred ,
Thanks for the reply. The newer version of Android (on a Samsung) seems to have removed the option of removed the option “Microsoft Exchange ActiveSync” under Settings->Account. Instead, the Gmail App offers to add an Exchange account. I used this one. The other options was to download the Outlook App from the Play store.
For test, I found an older device, Samsung Galaxy Note 4 now. Made a fresh install of z-push 2.5.2 on my server and configured as before and added a “Microsoft Exchange ActiveSync” account via Settings->Accounts.
When I open the default Email App, there are no Emails. The client seems to be synchronizing the INBOX. On the menu, I could click on “Show all folders” and the folder listing is right.
Here is the log when I open the App and the App tries to sync.08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] -------- Start 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] cmd='FolderSync' devType='SAMSUNGSMNF' devId='sec1c00ccb91b75f' getUser='mail_test' from='192.168.213.3' version='GIT' method='POST' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] Used timezone 'Europe/Amsterdam' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] Request::ProcessHeaders() ASVersion: 14.0 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ZPush::CommandNeedsProvisioning(9): true 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->GetState() read '2946' bytes from file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-devicedata' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ASDevice data loaded for user: 'mail_test' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] InterProcessData:__construct type: 'sec1c00ccb91b75f' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] TopCollector(): Initialized mutexid Resource id #20 and memid Resource id #21. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] InterProcessData:__construct type: 'sec1c00ccb91b75f' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] LoopDetection(): Initialized mutexid Resource id #25 and memid Resource id #26. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ZPush::HierarchyCommand(9): true 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] DeviceManager->ProvisioningRequired('868885463') saved device key '868885463': false 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] DeviceManager->getPolicyName(): determined policy name: 'default' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ZPush::CommandNeedsAuthentication(9): true 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->Logon(): User 'mail_test' is authenticated on '{polaris.SERVER.com:143/imap/notls/norsh}' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ZPush::CommandNeedsPlainInput(9): false 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] I <FolderHierarchy:FolderSync> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] I <FolderHierarchy:SyncKey> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] I {d072e011-9d05-4bca-9edd-1ef59e402111}1 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] I </FolderHierarchy:SyncKey> 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] StateManager->loadHierarchyCache(): 'sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-hc-1' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->GetState() read '1345' bytes from file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-hc-1' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->GetState() read '603' bytes from file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-1' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->GetState() read '379' bytes from file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-fd' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] SyncParameters->UseCPO('DEFAULT') 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 7 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] I </FolderHierarchy:FolderSync> 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->GetState() read '1075' bytes from file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-bs-1586298301' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('Trash') = 09ee7691 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('Trash') = 09ee7691 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('Sent') = 514979a2 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('Sent') = 514979a2 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Test3.newfldintest3') = 890fc6ac 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Test3.newfldintest3') = 890fc6ac 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Gesendete Objekte') = 8727f8e2 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Gesendete Objekte') = 8727f8e2 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Gel&APY-schte Objekte') = 414da2d7 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Gel&APY-schte Objekte') = 414da2d7 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Entw&APw-rfe') = 3c3cfb64 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Entw&APw-rfe') = 3c3cfb64 08/04/2020 00:26:09 [19530] [ INFO] [mail_test] ExportChangesDiff->InitializeExporter(): Found '8' changes for 'hierarchy' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('68f4348a') = INBOX 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('68f4348a'): 'SyncFolder ( (S) serverid => 68f4348a (S) parentid => 0 (S) displayname => INBOX (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('68f4348a') = INBOX 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('68f4348a'): 'SyncFolder ( (S) serverid => 68f4348a (S) parentid => 0 (S) displayname => INBOX (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'INBOX' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('09ee7691') = Trash 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('09ee7691'): 'SyncFolder ( (S) serverid => 09ee7691 (S) parentid => 0 (S) displayname => Trash (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('09ee7691') = Trash 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('09ee7691'): 'SyncFolder ( (S) serverid => 09ee7691 (S) parentid => 0 (S) displayname => Trash (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Trash' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('514979a2') = Sent 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('514979a2'): 'SyncFolder ( (S) serverid => 514979a2 (S) parentid => 0 (S) displayname => Sent (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('514979a2') = Sent 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('514979a2'): 'SyncFolder ( (S) serverid => 514979a2 (S) parentid => 0 (S) displayname => Sent (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Sent' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('890fc6ac') = INBOX.Test3.newfldintest3 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('890fc6ac'): 'SyncFolder ( (S) serverid => 890fc6ac (S) parentid => 0c6d560b (S) displayname => newfldintest3 (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('890fc6ac') = INBOX.Test3.newfldintest3 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX.Test3') = 0c6d560b 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('890fc6ac'): 'SyncFolder ( (S) serverid => 890fc6ac (S) parentid => 0c6d560b (S) displayname => newfldintest3 (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] HierarchyCache: AddFolder() serverid: 890fc6ac displayname: newfldintest3 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('0c6d560b') = INBOX.Test3 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('0c6d560b'): 'SyncFolder ( (S) serverid => 0c6d560b (S) parentid => 68f4348a (S) displayname => Test3 (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('0c6d560b') = INBOX.Test3 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('0c6d560b'): 'SyncFolder ( (S) serverid => 0c6d560b (S) parentid => 68f4348a (S) displayname => Test3 (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Test3' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('8727f8e2') = INBOX.Gesendete Objekte 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('8727f8e2'): 'SyncFolder ( (S) serverid => 8727f8e2 (S) parentid => 68f4348a (S) displayname => Gesendete Objekte (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('8727f8e2') = INBOX.Gesendete Objekte 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('8727f8e2'): 'SyncFolder ( (S) serverid => 8727f8e2 (S) parentid => 68f4348a (S) displayname => Gesendete Objekte (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Gesendete Objekte' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('414da2d7') = INBOX.Gel&APY-schte Objekte 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('414da2d7'): 'SyncFolder ( (S) serverid => 414da2d7 (S) parentid => 68f4348a (S) displayname => Gelöschte Objekte (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('414da2d7') = INBOX.Gel&APY-schte Objekte 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('414da2d7'): 'SyncFolder ( (S) serverid => 414da2d7 (S) parentid => 68f4348a (S) displayname => Gelöschte Objekte (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Gelöschte Objekte' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('3c3cfb64') = INBOX.Entw&APw-rfe 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('3c3cfb64'): 'SyncFolder ( (S) serverid => 3c3cfb64 (S) parentid => 68f4348a (S) displayname => Entwürfe (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getImapIdFromFolderId('3c3cfb64') = INBOX.Entw&APw-rfe 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->getFolderIdFromImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->convertImapId('INBOX') = 68f4348a 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->GetFolder('3c3cfb64'): 'SyncFolder ( (S) serverid => 3c3cfb64 (S) parentid => 68f4348a (S) displayname => Entwürfe (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 )' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ChangesMemoryWrapper->ImportFolderChange(): Change for folder 'Entwürfe' will not be sent as modification is not relevant. 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:FolderSync> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:Status> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O 1 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:Status> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:SyncKey> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O {d072e011-9d05-4bca-9edd-1ef59e402111}2 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:SyncKey> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:Changes> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:Count> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O 1 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:Count> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:Add> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:ServerEntryId> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O 890fc6ac 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:ServerEntryId> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:ParentId> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O 0c6d560b 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:ParentId> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:DisplayName> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O newfldintest3 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:DisplayName> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O <FolderHierarchy:Type> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O 12 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:Type> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:Add> 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:Changes> 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 8 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->SetState() written 1537 bytes on file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-hc-2' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->SetState() written 696 bytes on file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-2' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] SyncCollections::InvalidatePingableFlags(): Invalidating now 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->SetState() written 379 bytes on file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-d072e011-9d05-4bca-9edd-1ef59e402111-fd' 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] O </FolderHierarchy:FolderSync> 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] WBXMLEncoder->endTag() WBXML output completed 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] WBXML-OUT: AwFqAAAHVkwDMQABUgN7ZDA3MmUwMTEtOWQwNS00YmNhLTllZGQtMWVmNTllNDAyMTExfTIAAU5XAzEAAU9IAzg5MGZjNmFjAAFJAzBjNmQ1NjBiAAFHA25ld2ZsZGludGVzdDMAAUoDMTIAAQEBAQ== 08/04/2020 00:26:09 [19530] [WBXML] [mail_test] WBXML-IN : AwFqAAAHVlIDe2QwNzJlMDExLTlkMDUtNGJjYS05ZWRkLTFlZjU5ZTQwMjExMX0xAAEB 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] BackendIMAP->close_connection(): disconnected from IMAP server 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->SetState() written 1075 bytes on file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-bs-1586298301' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] DeviceManager->Save(): Device data changed 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] FileStateMachine->SetState() written 2982 bytes on file: '/var/www/zpush.SERVER.com/state/f/5/sec1c00ccb91b75f-devicedata' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] DeviceManager->Save(): Device data saved 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] LoopDetection->ProcessLoopDetectionTerminate() 08/04/2020 00:26:09 [19530] [ INFO] [mail_test] cmd='FolderSync' memory='2.07 MiB/2.00 MiB' time='0.11s' devType='SAMSUNGSMNF' devId='sec1c00ccb91b75f' getUser='mail_test' from='192.168.213.3' idle='0s' version='GIT' method='POST' httpcode='200' 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] -------- End
The error log does not produce new messages during this sync phase. The only entries are from the account creation phase, which is as follows.
08/04/2020 00:25:00 [ 3979] [WARN] [mail_test] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8) 08/04/2020 00:25:00 [ 3993] [FATAL] [mail_test] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 08/04/2020 00:25:11 [20279] [WARN] [mail_test] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8)
I would be grateful for pointers as to what is going wrong.
Thank you,
Elan -
Hi @elan,
@elan said in Timeout message when fetching mails - empty inbox:
Hi @Manfred ,
Thanks for the reply. The newer version of Android (on a Samsung) seems to have removed the option of removed the option “Microsoft Exchange ActiveSync” under Settings->Account. Instead, the Gmail App offers to add an Exchange account. I used this one. The other options was to download the Outlook App from the Play store.That’s strange. I have a Samsung device with Android 10 and there’s “Microsoft Exchange ActiveSync” type if I select “Add account”.
For test, I found an older device, Samsung Galaxy Note 4 now. Made a fresh install of z-push 2.5.2 on my server and configured as before and added a “Microsoft Exchange ActiveSync” account via Settings->Accounts.
When I open the default Email App, there are no Emails. The client seems to be synchronizing the INBOX. On the menu, I could click on “Show all folders” and the folder listing is right.
Here is the log when I open the App and the App tries to sync.08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] -------- Start 08/04/2020 00:26:09 [19530] [DEBUG] [mail_test] cmd='FolderSync' devType='SAMSUNGSMNF' devId='sec1c00ccb91b75f' getUser='mail_test' from='192.168.213.3' version='GIT' method='POST'
That’s a FolderSync request, not Sync and though not helpful.
Manfred