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 log

    02/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.


  • Kopano

    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


  • Kopano

    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


Log in to reply