sync runs until memory is exhausted, no mails sync'd



  • Hi,

    I am trying to get z-push working on an Ubuntu 16.04 machine with dovecot (i.e. IMAP backend). No mails are being pushed to an iOS phone.

    When I started trying z-push (installing z-push-common, z-push-config-apache, z-push-backend-imap and z-push-ipc-sharedmemory from the repo), I had errors in z-push-error.log like:

    30/11/2017 20:08:22 [13300] [ERROR] [user@domain.com] LoopDetection->ProcessLoopDetectionPreviousConnectionFailed(): Command 'FolderSync' at 30/11/2017 09:20:32 with pid '28529' terminated unexpectedly or is still running.
    30/11/2017 20:08:22 [13300] [ERROR] [user@domain.com] Please check your logs for this PID and errors like PHP-Fatals or Apache segmentation faults and report your results to the Z-Push dev team.
    

    I played around with the “php_value memory_limit” setting. It’s now at 1024 MB, and that error is not showing in my log anymore. However, there is still a related error in apache’s error log.

    The test account has quite some mails. However, my hope was that with setting IMAP_EXCLUDED_FOLDERS to ‘dovecot.sieve|Archiv|Mailing’ I would exclude everything but the Inbox. And the Inbox is rather small with just 21 mails in there. Not sure this is working, though. Because after I initiate a sync request from the phone, an apache and dovecot-imap task are running for quite some time with high CPU load, filling memory, until there is a memory-exhausted-error in apache’s log file.

    I don’t know what the error is. And the z-push logfile is rather small, despite LOGLEVEL_WBXML.

    Apache2 error.log:

    [Sat Dec 02 14:35:53.918594 2017] [:error] [pid 9308] [client 192.168.5.10:56449] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 262144 bytes) in Unknown on line 0
    [Sat Dec 02 15:12:56.398032 2017] [:error] [pid 28820] [client 192.168.5.10:56478] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 262144 bytes) in /usr/share/z-push/lib/core/stateobject.php on line 124
    [Sat Dec 02 15:12:56.398713 2017] [:error] [pid 28820] [client 192.168.5.10:56478] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 262144 bytes) in Unknown on line 0
    [Sat Dec 02 15:34:22.478121 2017] [:error] [pid 21100] [client 192.168.5.10:56617] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 262144 bytes) in /usr/share/z-push/lib/core/stateobject.php on line 124
    [Sat Dec 02 15:34:22.478757 2017] [:error] [pid 21100] [client 192.168.5.10:56617] PHP Fatal error:  Allowed memory size of 1073741824 bytes exhausted (tried to allocate 262144 bytes) in Unknown on line 0
    

    z-push.log:

    02/12/2017 07:00:44 [28423] [WARN] [user@domain.com] /usr/share/z-push/vendor/composer/ClassLoader.php:412 include(/usr/share/z-push/vendor/composer/../../backend/combined/combined.php): failed to open stream: No such file or directory (2)
    02/12/2017 07:00:44 [28423] [WARN] [user@domain.com] /usr/share/z-push/vendor/composer/ClassLoader.php:412 include(): Failed opening '/usr/share/z-push/vendor/composer/../../backend/combined/combined.php' for inclusion (include_path='.:/usr/share/php') (2)
    02/12/2017 07:00:44 [28423] [ INFO] [user@domain.com] StateNotFoundException: FileStateMachine->GetState(): Could not locate state '/var/lib/z-push/g/o/dk7u8vghd56hte5c2b4pkqmdog-bs-1512131902' - code: 0 - file: /usr/share/z-push/lib/default/filestatemachine.php:119
    02/12/2017 07:00:44 [28423] [ INFO] [user@domain.com] ExportChangesDiff->InitializeExporter(): Found '6' changes for 'hierarchy'
    02/12/2017 07:18:10 [28423] [WARN] [user@domain.com] Unknown:0 Unknown: SECURITY PROBLEM: insecure server advertised AUTH=PLAIN (errflg=1) (8)
    

    Config:

    config.php:

        define('TIMEZONE', 'Europe/Berlin');
        define('BASE_PATH', dirname($_SERVER['SCRIPT_FILENAME']). '/');
        define('SCRIPT_TIMEOUT', 0);
        define('USE_X_FORWARDED_FOR_HEADER', false);
        define("CERTIFICATE_OWNER_PARAMETER", "SSL_CLIENT_S_DN_CN");
        define('STATE_DIR', '/var/lib/z-push/');
        define('LOGFILEDIR', '/var/log/z-push/');
        define('LOGFILE', LOGFILEDIR . 'z-push.log');
        define('LOGERRORFILE', LOGFILEDIR . 'z-push-error.log');
        define('LOGLEVEL', LOGLEVEL_WBXML);
        define('LOGAUTHFAIL', true);
        define('LOGUSERLEVEL', LOGLEVEL_DEVICEID);
        $specialLogUsers = array('');
        define('PROVISIONING', true);
        define('LOOSE_PROVISIONING', false);
        define('SYNC_CONFLICT_DEFAULT', SYNC_CONFLICT_OVERWRITE_PIM);
        define('SYNC_FILTERTIME_MAX', SYNC_FILTERTYPE_ALL);
        define('PING_INTERVAL', 30);
        define('SINK_FORCERECHECK', 300);
        define('FILEAS_ORDER', SYNC_FILEAS_FIRSTLAST);
        define('SYNC_MAX_ITEMS', 100);
        define('UNSET_UNDEFINED_PROPERTIES', false);
        define('SYNC_CONTACTS_MAXPICTURESIZE', 49152);
        define('ALLOW_WEBSERVICE_USERS_ACCESS', false);
        define('BACKEND_PROVIDER', 'BackendIMAP');
        define('SEARCH_PROVIDER', '');
        define('SEARCH_WAIT', 10);
        define('SEARCH_MAXRESULTS', 10);
        $additionalFolders = array(
            array(
                'store'     => "SYSTEM",
                'folderid'  => "",
                'name'      => "Public Contacts",
                'type'      => SYNC_FOLDER_TYPE_USER_CONTACT,
            ),
        );
    

    imap.conf.php:

    define('IMAP_SERVER', 'mail.domain.com');
    define('IMAP_PORT', 143);
    define('IMAP_OPTIONS', '/notls/norsh');
    define('IMAP_AUTOSEEN_ON_DELETE', false);
    define('IMAP_FOLDER_CONFIGURED', true);
    define('IMAP_FOLDER_PREFIX', 'INBOX');
    define('IMAP_FOLDER_PREFIX_IN_INBOX', true);
    define('IMAP_FOLDER_INBOX', 'INBOX');
    define('IMAP_FOLDER_SENT', 'SENT');
    define('IMAP_FOLDER_DRAFT', 'DRAFTS');
    define('IMAP_FOLDER_TRASH', 'TRASH');
    define('IMAP_FOLDER_SPAM', 'SPAM');
    define('IMAP_FOLDER_ARCHIVE', 'ARCHIV');
    define('IMAP_INLINE_FORWARD', true);
    define('IMAP_EXCLUDED_FOLDERS', 'dovecot.sieve|Archiv|Mailing');
    define('IMAP_DEFAULTFROM', '');
    define('IMAP_FROM_SQL_DSN', '');
    define('IMAP_FROM_SQL_USER', '');
    define('IMAP_FROM_SQL_PASSWORD', '');
    define('IMAP_FROM_SQL_OPTIONS', serialize(array(PDO::ATTR_PERSISTENT => true)));
    define('IMAP_FROM_SQL_QUERY', "select first_name, last_name, mail_address from users where mail_address = '#username@#domain'");
    define('IMAP_FROM_SQL_FIELDS', serialize(array('first_name', 'last_name', 'mail_address')));
    define('IMAP_FROM_SQL_FROM', '#first_name #last_name <#mail_address>');
    define('IMAP_FROM_SQL_FULLNAME', '#first_name #last_name');
    define('IMAP_FROM_LDAP_SERVER', 'localhost');
    define('IMAP_FROM_LDAP_SERVER_PORT', '389');
    define('IMAP_FROM_LDAP_USER', 'cn=zpush,ou=servers,dc=zpush,dc=org');
    define('IMAP_FROM_LDAP_PASSWORD', 'password');
    define('IMAP_FROM_LDAP_BASE', 'dc=zpush,dc=org');
    define('IMAP_FROM_LDAP_QUERY', '(mail=#username@#domain)');
    define('IMAP_FROM_LDAP_FIELDS', serialize(array('givenname', 'sn', 'mail')));
    define('IMAP_FROM_LDAP_FROM', '#givenname #sn <#mail>');
    define('IMAP_FROM_LDAP_FULLNAME', '#givenname #sn');
    define('IMAP_SMTP_METHOD', 'mail');
    global $imap_smtp_params;
    $imap_smtp_params = array();
    define('MAIL_MIMEPART_CRLF', "\r\n");
    define('SYSTEM_MIME_TYPES_MAPPING', '/etc/mime.types');
    define('IMAP_MEETING_USE_CALDAV', false);
    

    z-push.conf.php:

        define('TIMEZONE', '');
        define('BASE_PATH', dirname($_SERVER['SCRIPT_FILENAME']). '/');
        define('SCRIPT_TIMEOUT', 0);
        define('USE_X_FORWARDED_FOR_HEADER', false);
        define("CERTIFICATE_OWNER_PARAMETER", "SSL_CLIENT_S_DN_CN");
        define('USE_FULLEMAIL_FOR_LOGIN', true);
        define('STATE_MACHINE', 'FILE');
        define('STATE_DIR', '/var/lib/z-push/');
        define('IPC_PROVIDER', '');
        define('LOGBACKEND', 'filelog');
        define('LOGLEVEL', LOGLEVEL_INFO);
        define('LOGAUTHFAIL', false);
        define('LOGUSERLEVEL', LOGLEVEL_DEVICEID);
        $specialLogUsers = array();
        define('LOGFILEDIR', '/var/log/z-push/');
        define('LOGFILE', LOGFILEDIR . 'z-push.log');
        define('LOGERRORFILE', LOGFILEDIR . 'z-push-error.log');
        define('LOG_SYSLOG_HOST', false);
        define('LOG_SYSLOG_PORT', 514);
        define('LOG_SYSLOG_PROGRAM', 'z-push');
        define('LOG_SYSLOG_FACILITY', LOG_LOCAL0);
        define('PROVISIONING', true);
        define('LOOSE_PROVISIONING', false);
        define('PROVISIONING_POLICYFILE', 'policies.ini');
        define('SYNC_CONFLICT_DEFAULT', SYNC_CONFLICT_OVERWRITE_PIM);
        define('SYNC_FILTERTIME_MAX', SYNC_FILTERTYPE_ALL);
        define('PING_INTERVAL', 30);
        define('FILEAS_ORDER', SYNC_FILEAS_LASTFIRST);
        define('SYNC_MAX_ITEMS', 512);
        define('UNSET_UNDEFINED_PROPERTIES', false);
        define('SYNC_CONTACTS_MAXPICTURESIZE', 5242880);
        define('ALLOW_WEBSERVICE_USERS_ACCESS', false);
        define('USE_PARTIAL_FOLDERSYNC', false);
        define('PING_LOWER_BOUND_LIFETIME', false);
        define('PING_HIGHER_BOUND_LIFETIME', false);
        define('SYNC_TIMEOUT_MEDIUM_DEVICETYPES', "SAMSUNGGTI");
        define('SYNC_TIMEOUT_LONG_DEVICETYPES',   "iPod, iPad, iPhone, WP, WindowsOutlook, WindowsMail");
        define('RETRY_AFTER_DELAY', 300);
        define('BACKEND_PROVIDER', '');
        define('SEARCH_PROVIDER', '');
        define('SEARCH_WAIT', 10);
        define('SEARCH_MAXRESULTS', 10);
        define('KOE_CAPABILITY_GAB', true);
        define('KOE_CAPABILITY_RECEIVEFLAGS', true);
        define('KOE_CAPABILITY_SENDFLAGS', true);
        define('KOE_CAPABILITY_OOF', true);
        define('KOE_CAPABILITY_OOFTIMES', true);
        define('KOE_CAPABILITY_NOTES', true);
        define('KOE_CAPABILITY_SHAREDFOLDER', true);
        define('KOE_CAPABILITY_SENDAS', true);
        define('KOE_CAPABILITY_SECONDARYCONTACTS', true);
        define('KOE_CAPABILITY_SIGNATURES', true);
        define('KOE_CAPABILITY_RECEIPTS', true);
        define('KOE_GAB_STORE', 'SYSTEM');
        define('KOE_GAB_FOLDERID', '');
        define('KOE_GAB_NAME', 'Z-Push-KOE-GAB');
        $additionalFolders = array(
            array(
                'store'     => "SYSTEM",
                'folderid'  => "",
                'name'      => "Public Contacts",
                'type'      => SYNC_FOLDER_TYPE_USER_CONTACT,
            ),
        );
    
    


  • How have you installed z-push?

    In your config you show that you have set BackendIMAP yet, in your log it shows a failure to include combined.php which is for the combined backend.

    Your config looks to be a really old file - have you upgraded an old installation?


  • Kopano

    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-sharedmemory
    

    As 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') = INBOX
    

    z-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.


Log in to reply
 

Looks like your connection to Kopano Community Forum was lost, please wait while we try to reconnect.