sync runs until memory is exhausted, no mails sync'd
-
Hi OutOfIdeas,
how have you installed Z-Push? Using repositories or the .gz file?
Could you post the complete z-push.log on WBXML level?
Manfred
-
I installed z-push from the repos, which I had understood to be the recommended approach:
echo "deb http://repo.z-hub.io/z-push:/final/Ubuntu_16.04/ /" >/etc/apt/sources.list.d/z-push.list wget -qO - http://repo.z-hub.io/z-push:/final/Debian_8.0/Release.key | sudo apt-key add - apt update apt install z-push-common z-push-config-apache z-push-backend-imap apt install z-push-ipc-sharedmemoryAs to logging, config.php above contains
define('LOGLEVEL', LOGLEVEL_WBXML);Isn’t that what’s required to get WBXML level logging? The log really doesn’t contain more than what I posted, which is part of what I found a bit strange.
Or do I need to do something else?
-
It is concerning that you have both a config.php and a z-push.conf.php and obviously they are completely different.
If you installed clean from the respositories, config.php in the z-push directory should be a symlink to /etc/z-push/z-push.conf.php - so the two files should be identical (in fact the same file)
While you have DEBUG level set in your config.php file - your z-push.conf.php file has only INFO loglevel set.
You should eliminate the old config.php file and make sure that your config.php in the z-push folder is a link to /etc/z-push/z-push.conf.php - making sure to take across any settings you may have changed from default values.
Then, re-run your tests.
-
Thanks, I have removed /etc/z-push/config.php and linked /usr/share/z-push/config.php to /etc/z-push/zpush.conf.php. I have then also changed the loglevel in z-push.conf.php.
I’m still not getting e-mails onto my phone (rather an error that e-mails cannot be received), but the log file is much more verbose now:
07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] cmd='' devType='' devId='' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='OPTIONS' 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] BackendIMAP->Logon(): Excluding Folders (dovecot.sieve|Archiv|Mailing) 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] BackendIMAP->Logon(): User 'user@domain.com' is authenticated on '{mail.domain.com:143/imap/notls/norsh}' 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings 07/12/2017 11:53:00 [29112] [ INFO] [user@domain.com] Options request 07/12/2017 11:53:00 [29112] [ INFO] [user@domain.com] cmd='' memory='1.70 MiB/2.00 MiB' time='0.01s' devType='' devId='' getUser='user@domain.com' from='1.2.3.4' idle='0s' version='2.3.8+0-0' method='OPTIONS' httpcode='200' 07/12/2017 11:53:00 [29112] [DEBUG] [user@domain.com] -------- End 07/12/2017 11:53:00 [29112] [WARN] [user@domain.com] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8) 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] cmd='FolderSync' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='POST' 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] ZPush::CommandNeedsProvisioning(9): true 07/12/2017 11:53:00 [29021] [ INFO] [user@domain.com] ProvisioningRequiredException: Retry after sending a PROVISION command - code: 0 - file: /usr/share/z-push/index.php:82 07/12/2017 11:53:00 [29021] [ INFO] [user@domain.com] User-agent: 'Apple-iPhone10C6/1503.114' 07/12/2017 11:53:00 [29021] [FATAL] [user@domain.com] Exception: (ProvisioningRequiredException) - Retry after sending a PROVISION command 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] TopCollector(): Initialized mutexid Resource id #20 and memid Resource id #21. 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 07/12/2017 11:53:00 [29021] [ INFO] [user@domain.com] cmd='FolderSync' memory='1.70 MiB/2.00 MiB' time='0.01s' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' idle='0s' version='2.3.8+0-0' method='POST' httpcode='449' 07/12/2017 11:53:00 [29021] [DEBUG] [user@domain.com] -------- End 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] cmd='' devType='' devId='' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='OPTIONS' 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] BackendIMAP->Logon(): Excluding Folders (dovecot.sieve|Archiv|Mailing) 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] BackendIMAP->Logon(): User 'user@domain.com' is authenticated on '{mail.domain.com:143/imap/notls/norsh}' 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] NoPostRequestException: Options request - code: 1 - file: /usr/share/z-push/index.php:66 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings 07/12/2017 11:53:00 [29113] [ INFO] [user@domain.com] Options request 07/12/2017 11:53:00 [29113] [ INFO] [user@domain.com] cmd='' memory='1.59 MiB/2.00 MiB' time='0.01s' devType='' devId='' getUser='user@domain.com' from='1.2.3.4' idle='0s' version='2.3.8+0-0' method='OPTIONS' httpcode='200' 07/12/2017 11:53:00 [29113] [DEBUG] [user@domain.com] -------- End 07/12/2017 11:53:00 [29113] [WARN] [user@domain.com] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8) 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] cmd='Provision' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='POST' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] ZPush::CommandNeedsProvisioning(20): false 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] ZPush::CommandNeedsAuthentication(20): false 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] FileStateMachine->GetState() read '1026' bytes from file: '/var/lib/z-push/g/o/dk7dogghdoghte5cdogpkkmdog-devicedata' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] ASDevice data loaded for user: 'user@domain.com' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] TopCollector(): Initialized mutexid Resource id #18 and memid Resource id #19. 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] LoopDetection(): Initialized mutexid Resource id #22 and memid Resource id #23. 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] ZPush::HierarchyCommand(20): false 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] ZPush::CommandNeedsPlainInput(20): false 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] RequestProcessor::HandleProvision(): Forcing delayed Authentication 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] BackendIMAP->Logon(): Excluding Folders (dovecot.sieve|Archiv|Mailing) 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] BackendIMAP->Logon(): User 'user@domain.com' is authenticated on '{mail.domain.com:143/imap/notls/norsh}' 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I <Provision:Provision> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I <Provision:Policies> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I <Provision:Policy> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I <Provision:PolicyType> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I MS-EAS-Provisioning-WBXML 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I </Provision:PolicyType> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I </Provision:Policy> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I </Provision:Policies> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] I </Provision:Provision> 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:Provision> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:Status> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O 1 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O </Provision:Status> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:Policies> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:Policy> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:PolicyType> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O MS-EAS-Provisioning-WBXML 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O </Provision:PolicyType> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:Status> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O 1 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O </Provision:Status> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O <Provision:PolicyKey> 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O 612194185 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] O </Provision:PolicyKey> 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] DeviceManager->getPolicyName(): determined policy name: 'default' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. [Policies skipped for readability] 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] WBXML-OUT: AwFqAAAORUsDMQABRkdIA01TLUVBUy1Qcm92aXNpb25pbmctV0JYTUwAAUsDMQABSQM2MTIxOTQxODUAAUpNTgMwAAFPAzAAAVEDMAABUAMwAAFTAzEAAVQDNAABVQM5MDAAAVYDOAABF1gDMQABWQMwAAFaAzAAAVsDMQABXAMxAAFdAzAAAV4DMQABXwMxAAFgAzMAAWEDMQABYgMxAAFjAzEAAWQDMgABZQMxAAFmAzAAAWcDMQABaAMwAAFpAzEAAWoDMAABawMtMQABbAMtMQABbQMwAAFuAzAAAW8DMAABcAMwAAFxAzIAAXIDMQABcwMxAAF0AzEAAXUDMQABdgMxAAE3OQEBAQEB 07/12/2017 11:53:01 [29017] [WBXML] [user@domain.com] WBXML-IN : AwFqAAAORUZHSANNUy1FQVMtUHJvdmlzaW9uaW5nLVdCWE1MAAEBAQE= 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] BackendIMAP->close_connection(): disconnected from IMAP server 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] LoopDetection->ProcessLoopDetectionTerminate() 07/12/2017 11:53:01 [29017] [ INFO] [user@domain.com] cmd='Provision' memory='1.91 MiB/2.00 MiB' time='0.02s' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' idle='0s' version='2.3.8+0-0' method='POST' httpcode='200' 07/12/2017 11:53:01 [29017] [DEBUG] [user@domain.com] -------- End 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] cmd='Provision' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='POST' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] ZPush::CommandNeedsProvisioning(20): false 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] ZPush::CommandNeedsAuthentication(20): false 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] FileStateMachine->GetState() read '1026' bytes from file: '/var/lib/z-push/g/o/dk7dogghdoghte5cdogpkkmdog-devicedata' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] ASDevice data loaded for user: 'user@domain.com' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] TopCollector(): Initialized mutexid Resource id #18 and memid Resource id #19. 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] LoopDetection(): Initialized mutexid Resource id #22 and memid Resource id #23. 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] ZPush::HierarchyCommand(20): false 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] ZPush::CommandNeedsPlainInput(20): false 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] RequestProcessor::HandleProvision(): Forcing delayed Authentication 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] BackendIMAP->Logon(): Excluding Folders (dovecot.sieve|Archiv|Mailing) 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] BackendIMAP->Logon(): User 'user@domain.com' is authenticated on '{mail.domain.com:143/imap/notls/norsh}' 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:Provision> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:Policies> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:Policy> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:PolicyType> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I MS-EAS-Provisioning-WBXML 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:PolicyType> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:PolicyKey> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I 612194185 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:PolicyKey> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I <Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I 1 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:Policy> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:Policies> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] I </Provision:Provision> 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] DeviceManager->SetPolicyKey('721213583') 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:Provision> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O 1 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:Policies> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:Policy> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:PolicyType> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O MS-EAS-Provisioning-WBXML 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:PolicyType> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O 1 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:Status> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O <Provision:PolicyKey> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O 721213583 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:PolicyKey> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:Policy> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:Policies> 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] O </Provision:Provision> 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] WBXMLEncoder->endTag() WBXML output completed 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] WBXML-OUT: AwFqAAAORUsDMQABRkdIA01TLUVBUy1Qcm92aXNpb25pbmctV0JYTUwAAUsDMQABSQM3MjEyMTM1ODMAAQEBAQ== 07/12/2017 11:53:01 [29020] [WBXML] [user@domain.com] WBXML-IN : AwFqAAAORUZHSANNUy1FQVMtUHJvdmlzaW9uaW5nLVdCWE1MAAFJAzYxMjE5NDE4NQABSwMxAAEBAQE= 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] BackendIMAP->close_connection(): IMAP said: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] BackendIMAP->close_connection(): disconnected from IMAP server 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] DeviceManager->Save(): Device data changed 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] FileStateMachine->SetState() written 1026 bytes on file: '/var/lib/z-push/g/o/dk7dogghdoghte5cdogpkkmdog-devicedata' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] DeviceManager->Save(): Device data saved 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] LoopDetection->ProcessLoopDetectionTerminate() 07/12/2017 11:53:01 [29020] [ INFO] [user@domain.com] cmd='Provision' memory='1.75 MiB/2.00 MiB' time='0.01s' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' idle='0s' version='2.3.8+0-0' method='POST' httpcode='200' 07/12/2017 11:53:01 [29020] [DEBUG] [user@domain.com] -------- End 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] -------- Start 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] cmd='FolderSync' devType='iPhone' devId='dk7dogghdoghte5cdogpkkmdog' getUser='user@domain.com' from='1.2.3.4' version='2.3.8+0-0' method='POST' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Used timezone 'Europe/Amsterdam' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Request::ProcessHeaders() ASVersion: 14.0 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::CommandNeedsProvisioning(9): true 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] FileStateMachine->GetState() read '1026' bytes from file: '/var/lib/z-push/g/o/dk7dogghdoghte5cdogpkkmdog-devicedata' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ASDevice data loaded for user: 'user@domain.com' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] TopCollector(): Initialized mutexid Resource id #17 and memid Resource id #18. 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] TopCollector initialised with IPC provider 'IpcSharedMemoryProvider' with type '20' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] LoopDetection(): Initialized mutexid Resource id #21 and memid Resource id #22. 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] LoopDetection initialised with IPC provider 'IpcSharedMemoryProvider' with type '1337' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::HierarchyCommand(9): true 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] DeviceManager->ProvisioningRequired('721213583') saved device key '721213583': false 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] DeviceManager->getPolicyName(): determined policy name: 'default' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] DeviceManager->getProvisioningPolicies(): loaded 'default' policy. 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::CommandNeedsAuthentication(9): true 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->Logon(): Excluding Folders (dovecot.sieve|Archiv|Mailing) 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->Logon(): User 'user@domain.com' is authenticated on '{mail.domain.com:143/imap/notls/norsh}' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::CommandNeedsPlainInput(9): false 07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I <FolderHierarchy:FolderSync> 07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I <FolderHierarchy:SyncKey> 07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I 0 07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I </FolderHierarchy:SyncKey> 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0 07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I </FolderHierarchy:FolderSync> 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] LoopDetection->ProcessLoopDetectionAddStatus: 'hierarchy' with status 1 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] WBXMLEncoder->startWBXML() type: vnd.ms-sync.wbxml 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ExportChangesDiff->InitializeExporter(): Initializing folder diff engine 07/12/2017 11:53:01 [29021] [ INFO] [user@domain.com] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/g/o/dk7dogghdoghte5cdogpkkmdog-bs-1512131902' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Sent') IMAP cache folder not found, creating one 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Sent') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Sent') = 29738028 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Spam') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Spam') = bbad157f 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Pattern: <dovecot.sieve> found, excluding folder: '{mail.domain.com:143/imap/notls/norsh}INBOX.dovecot.sieve' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Notes') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Notes') = 55751364 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Trash') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Trash') = 6d093eb1 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Drafts') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Drafts') = f7ca868a 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Pattern: <Archiv> found, excluding folder: '{mail.domain.com:143/imap/notls/norsh}INBOX.Archives' [Tons of skipped folders] 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX') = not found 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX') = 4b03f4ee 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Sent') = 29738028 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Sent') = 29738028 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Spam') = bbad157f 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Spam') = bbad157f 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Pattern: <dovecot.sieve> found, excluding folder: '{mail.domain.com:143/imap/notls/norsh}INBOX.dovecot.sieve' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Notes') = 55751364 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Notes') = 55751364 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Trash') = 6d093eb1 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Trash') = 6d093eb1 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX.Drafts') = f7ca868a 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX.Drafts') = f7ca868a 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] Pattern: <Archiv> found, excluding folder: '{mail.domain.com:143/imap/notls/norsh}INBOX.Archives' [Tons of skipped folders] 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getFolderIdFromImapId('INBOX') = 4b03f4ee 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->convertImapId('INBOX') = 4b03f4ee 07/12/2017 11:53:01 [29021] [ INFO] [user@domain.com] ExportChangesDiff->InitializeExporter(): Found '6' changes for 'hierarchy' 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('29738028') = INBOX.Sent 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('29738028'): 'SyncFolder ( (S) serverid => 29738028 (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('29738028') = INBOX.Sent 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('29738028'): 'SyncFolder ( (S) serverid => 29738028 (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] HierarchyCache: AddFolder() serverid: 29738028 displayname: Sent 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('bbad157f') = INBOX.Spam 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('bbad157f'): 'SyncFolder ( (S) serverid => bbad157f (S) parentid => 0 (S) displayname => Junk (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('bbad157f') = INBOX.Spam 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('bbad157f'): 'SyncFolder ( (S) serverid => bbad157f (S) parentid => 0 (S) displayname => Junk (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] HierarchyCache: AddFolder() serverid: bbad157f displayname: Junk 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('55751364') = INBOX.Notes 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('55751364'): 'SyncFolder ( (S) serverid => 55751364 (S) parentid => 0 (S) displayname => Notes (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('55751364') = INBOX.Notes 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('55751364'): 'SyncFolder ( (S) serverid => 55751364 (S) parentid => 0 (S) displayname => Notes (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] HierarchyCache: AddFolder() serverid: 55751364 displayname: Notes 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('6d093eb1') = INBOX.Trash 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('6d093eb1'): 'SyncFolder ( (S) serverid => 6d093eb1 (S) parentid => 0 (S) displayname => Trash (S) type => 4 (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('6d093eb1') = INBOX.Trash 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('6d093eb1'): 'SyncFolder ( (S) serverid => 6d093eb1 (S) parentid => 0 (S) displayname => Trash (S) type => 4 (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] HierarchyCache: AddFolder() serverid: 6d093eb1 displayname: Trash 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('f7ca868a') = INBOX.Drafts 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('f7ca868a'): 'SyncFolder ( (S) serverid => f7ca868a (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('f7ca868a') = INBOX.Drafts 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->GetFolder('f7ca868a'): 'SyncFolder ( (S) serverid => f7ca868a (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/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] HierarchyCache: AddFolder() serverid: f7ca868a displayname: Drafts 07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] BackendIMAP->getImapIdFromFolderId('4b03f4ee') = INBOXz-push selects the right folders, but then, nothing appears to happen… Did I miss any important error message in this log?
[later]
Ah, the memory problem and my impatience again:
07/12/2017 12:13:58 [29019] [FATAL] [cvb@kruemel.org] Fatal error: /usr/share/z-push/backend/imap/imap.php:2344 - Allowed memory size of 1073741824 bytes exhausted (tried to allocate 4096 bytes) (1)There are 25 mails in the inbox, 15 in drafts, 0 in spam, 22 in trash, 80 in Sent. All other folders are excluded. Most existing mails are just a couple of k in size, none greater than 1 MB. What does z-push need more than a GB in memory for?
-
So, your log shows the "I"ncoming FolderSync request
07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I FolderHierarchy:FolderSync
07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I FolderHierarchy:SyncKey
07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I 0
07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I </FolderHierarchy:SyncKey>
07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::GetSupportedProtocolVersions(): 12.0,12.1,14.0
07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ZPush::GetSupportedCommands(): Sync,SendMail,SmartForward,SmartReply,GetAttachment,GetHierarchy,CreateCollection,DeleteCollection,MoveCollection,FolderSync,FolderCreate,FolderDelete,FolderUpdate,MoveItems,GetItemEstimate,MeetingResponse,ResolveRecipients,ValidateCert,Provision,Search,Ping,Notify,ItemOperations,Settings
07/12/2017 11:53:01 [29021] [DEBUG] [user@domain.com] ASDevice->GetHierarchyCache(): HierarchyCache is up - Cached objects: 0
07/12/2017 11:53:01 [29021] [WBXML] [user@domain.com] I </FolderHierarchy:FolderSync>and the selection of the folders.
Do you see the "O"utgoing FolderSync response in the log also?
If not, then it appears that the problem is with walking through the folder list returned by your server.
Have you used a “super” user account that has rights to everyones folders?
If you configure that same account in Thunderbird or a similar IMAP client - what can you see?
-
@liverpoolfcfan said in sync runs until memory is exhausted, no mails sync’d:
So, your log shows the "I"ncoming FolderSync request
Do you see the "O"utgoing FolderSync response in the log also?No, I posted the entire log (except for the parts I mentioned in []-brackets which I had left out. Nothing for O.
If not, then it appears that the problem is with walking through the folder list returned by your server.
Have you used a “super” user account that has rights to everyones folders?No, just a normal mail user.
If you configure that same account in Thunderbird or a similar IMAP client - what can you see?
Everything. The mail account is normally access through Thunderbird and the Apple Mail app, where it is configured as IMAP. No issues there.
What htop shows me, by the way, is an apache2 thread accumulating memory, keeping a dovecot imap thread very busy. Until the point when the memory error occurs. There is no related log output from z-push.
-
@outofideas said in sync runs until memory is exhausted, no mails sync’d:
Everything. The mail account is normally access through Thunderbird and the Apple Mail app
What exactly is Everything? That is my question.
You are trying to exclude some stuff in your configuration. Exactly how many folders are there in the account if you don’t exclude anything?
-
Sorry, didn’t get that. There are 15 folders below “Archive” (one with another subfolder), and 49 Folders below “Mailing-List”. The entire maildir for this account is 745 MB in size.
-
@outofideas If you remove your exclude rules does the initial FolderSync work?
-
Ok, so I changed in /etc/z-push/imap.conf.php
define('IMAP_EXCLUDED_FOLDERS', 'dovecot.sieve|Archiv|Mailing');to
define('IMAP_EXCLUDED_FOLDERS', 'dovecot.sieve');or
define('IMAP_EXCLUDED_FOLDERS', '');Obviously, z-push.log is much larger now, as it (within a second) works through all folders. But after that second, nothing happens, then I get an error on my phone that e-mails could not be received, as the connection with the server has failed. And minutes later, there is the old error in the log again:
08/12/2017 18:42:51 [ 3138] [FATAL] [user@domain.com] Fatal error: /usr/share/z-push/backend/imap/imap.php:2344 - Allowed memory size of 1073741824 bytes exhausted (tried to allocate 4096 bytes) (1)Other symptoms are also the same, i.e. long running dovecot-imap (high CPU consumption) and apache2 (high memory consumption) threads on the machine.
