Navigation

    Kopano
    • Register
    • Login
    • Search
    • Categories
    • Get Official Kopano Support
    • Recent
    Statement regarding the closure of the Kopano community forum and the end of the community edition

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

    Z-Push when using other backends
    3
    12
    2545
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • OutOfIdeas
      OutOfIdeas last edited by

      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,
        ),
    );
      1 Reply Last reply Reply Quote 0
      • liverpoolfcfan
        liverpoolfcfan last edited by

        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?

        1 Reply Last reply Reply Quote 0
        • Manfred
          Manfred Kopano last edited by

          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

          1 Reply Last reply Reply Quote 0
          • OutOfIdeas
            OutOfIdeas last edited by

            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?

            1 Reply Last reply Reply Quote 0
            • liverpoolfcfan
              liverpoolfcfan last edited by

              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.

              1 Reply Last reply Reply Quote 1
              • OutOfIdeas
                OutOfIdeas last edited by

                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?

                1 Reply Last reply Reply Quote 0
                • liverpoolfcfan
                  liverpoolfcfan last edited by liverpoolfcfan

                  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?

                  OutOfIdeas 1 Reply Last reply Reply Quote 0
                  • OutOfIdeas
                    OutOfIdeas @liverpoolfcfan last edited by

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

                    liverpoolfcfan 1 Reply Last reply Reply Quote 0
                    • liverpoolfcfan
                      liverpoolfcfan @OutOfIdeas last edited by

                      @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?

                      1 Reply Last reply Reply Quote 0
                      • OutOfIdeas
                        OutOfIdeas last edited by

                        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.

                        liverpoolfcfan 1 Reply Last reply Reply Quote 0
                        • liverpoolfcfan
                          liverpoolfcfan @OutOfIdeas last edited by

                          @outofideas If you remove your exclude rules does the initial FolderSync work?

                          1 Reply Last reply Reply Quote 0
                          • OutOfIdeas
                            OutOfIdeas last edited by

                            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.

                            1 Reply Last reply Reply Quote 0
                            • First post
                              Last post