outgoing email keeps on sending the same message

remcov

I need some help. My tech-guy installed for me kopano community edition, multi-tenancy enabaled
opensuse thumbleweed, Kopano Core: 8.3.3.24-37, WebApp: 3.3.1

I have several problems with this setup. The biggest problem is that last 2 weeks sometimes sending email from outlook 2013/2016 is a big problem: outgoing email gets into a loop, and the same message is being send for 5 or 10 times, on different accounts / networks . (I guess Z-push?)

Also I have a problem with my windows phone, that my email frequently can’t be synced, untill I restart my phone. I do have server access, have log files but to be honest, don’t know what to check.

I am looking for a solution for this problem, or if anybody is interested someone to push the right buttons to get it right, and install some other modules like the files-module (of course this can be paid job)

Thanx, Remco.

Coffee_is_life

hello @remcov,

i recommend checking spooler-log (default /var/log/kopano/spooler.log)
and z-push log (default /var/log/z-push/z-push.log)

if these files doesnt exist, check you config file (under /etc/kopano/spooler.cfg) for the log destination
and for z-push there should be /etc/z-push/z-push.conf.php

coffee_is_life

remcov

Hello coffee_is_life, thanx for your swift reply.
Here I have some log entry’s that come bag most of the time. (changed the @ domainnames for privacy)
I think it might be a problem with max synctime and the growing data that needs to be synced?

Z-push.log

03/04/2018 20:19:44 [ 4022] [ INFO] [vincent@domein2.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 540 seconds)
03/04/2018 20:19:59 [ 3296] [ INFO] [vincent@domein2.nl] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 90s from 540s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
03/04/2018 20:19:59 [ 3296] [ INFO] [vincent@domein2.nl] cmd='Ping' memory='2.44 MiB/2.00 MiB' time='90.10s' devType='Outlook' devId='1ca749486aa9aebd' getUser='vincent@domein2.nl\vincent@domein2.nl' from='52.232.100.50' idle='90s' version='2.3.8+0' method='POST' httpcode='200'
03/04/2018 20:19:59 [ 3296] [ INFO] [support@domein3.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)
03/04/2018 20:19:59 [ 3981] [ INFO] [support@domein3.nl] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 60s from 3540s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
03/04/2018 20:19:59 [ 3981] [ INFO] [support@domein3.nl] cmd='Ping' memory='2.37 MiB/4.00 MiB' time='60.08s' devType='WindowsOutlook' devId='c99f863c8db84ed896d70e1708b31a47' getUser='support@domein3.nl' from='212.83.85.184' idle='60s' version='2.3.8+0' method='POST' httpcode='200'
03/04/2018 20:19:59 [ 4341] [ INFO] [info@domein3.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)
03/04/2018 20:19:59 [ 3980] [ INFO] [info@domein3.nl] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 60s from 3540s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
03/04/2018 20:19:59 [ 3980] [ INFO] [info@domein3.nl] cmd='Ping' memory='2.55 MiB/4.00 MiB' time='60.10s' devType='WindowsOutlook' devId='7193d7592b474e27a5ea9575720c3dbc' getUser='info@domein3.nl' from='212.83.85.184' idle='60s' version='2.3.8+0' method='POST' httpcode='200'
03/04/2018 20:20:00 [ 3981] [ INFO] [info@domein1.nl.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)
03/04/2018 20:20:00 [ 2491] [ INFO] [info@domein1.nl.nl] StatusException: SyncCollections->CheckForChanges(): Timeout forced after 60s from 3540s due to other process - code: 3 - file: /usr/share/z-push/lib/core/synccollections.php:579
03/04/2018 20:20:00 [ 2491] [ INFO] [info@domein1.nl.nl] cmd='Ping' memory='3.20 MiB/4.00 MiB' time='60.14s' devType='WindowsOutlook' devId='0a503f132a6d469faef59252e46963ce' getUser='info@domein1.nl.nl' from='212.83.85.184' idle='60s' version='2.3.8+0' method='POST' httpcode='200'
03/04/2018 20:20:02 [ 3980] [ INFO] [info@domein1.nl.nl] cmd='Sync' memory='2.07 MiB/4.00 MiB' time='0.09s' devType='WP' devId='86208140cfe5466af06b99f2961fb600' getUser='info@domein1.nl.nl' from='212.83.85.184' idle='0s' version='2.3.8+0' method='POST' httpcode='200'
03/04/2018 20:20:02 [ 2491] [ INFO] [info@domein1.nl.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 900 seconds)
03/04/2018 20:20:02 [ 2491] [ INFO] [info@domein1.nl.nl] StateInvalidException: Unexpected synckey value oldcounter: '81' synckey: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}82' internal key: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}' - code: 0 - file: /usr/share/z-push/lib/core/statemanager.php:236
03/04/2018 20:20:02 [ 2491] [FATAL] [info@domein1.nl.nl] WBXML 10K debug data: AwFqAEVpAzkwMAABJgE=
03/04/2018 20:20:02 [ 2491] [ INFO] [info@domein1.nl.nl] User-agent: 'unknown'
03/04/2018 20:20:02 [ 2491] [FATAL] [info@domein1.nl.nl] Exception: (StateInvalidException) - Unexpected synckey value oldcounter: '81' synckey: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}82' internal key: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}'
03/04/2018 20:20:02 [ 2491] [ INFO] [info@domein1.nl.nl] cmd='Sync' memory='6.67 MiB/12.01 MiB' time='0.12s' devType='WP' devId='86208140cfe5466af06b99f2961fb600' getUser='info@domein1.nl.nl' from='212.83.85.184' idle='0s' version='2.3.8+0' method='POST' httpcode='500'
03/04/2018 20:20:30 [ 4370] [ INFO] [orders@domein1.nl.nl] SyncCollections->CheckForChanges(): Waiting for store changes... (lifetime 3540 seconds)

Z-push error.log >> This is possible my windowsphone bug

10K debug data: AwFqAEVpAzkwMAABJgE=
03/04/2018 20:19:05 [ 2488] [FATAL] [info@domein1.nl.nl] Exception: (StateInvalidException) - Unexpected synckey value oldcounter: '81' synckey: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}82' internal key: '{3e4c1f5a-bc18-4a5c-9787-10dfa33c37c2}'
13/03/2018 17:39:12 [20972] [WARN] [info@domein1.nl] /usr/share/z-push/index.php:118 ob_end_clean(): failed to delete buffer. No buffer to delete (8)

and a older one about loop detected on my account

02/01/2018 07:21:09 [16601] [WARN] [info@domein1.nl.nl] Mobile loop detected! Messages sent to the mobile will be restricted to 1 items in order to identify the conflict

Server.Log

Tue Apr  3 07:37:05 2018: [warning] Unable to retrieve parents for relation groupmember: uid attribute not found.
Tue Apr  3 07:54:26 2018: [warning] Previous message logged 100 times

Spooler.log = 0kb

Coffee_is_life

good morning @remcov,

for the timeout, there schould be some lines in z-push-conf.php:

 // Maximum response time
    // Mobiles implement different timeouts to their TCP/IP connections. Android devices for example
    // have a hard timeout of 30 seconds. If the server is not able to answer a request within this timeframe,
    // the answer will not be recieved and the device will send a new one overloading the server.
    // There are three categories
    //   - Short timeout  - server has up within 30 seconds - is automatically applied for not categorized types
    //   - Medium timeout - server has up to 90 seconds to respond
    //   - Long timeout   - server has up to 4 minutes to respond
    // If a timeout is almost reached the server will break and sent the results it has until this
    // point. You can add DeviceType strings to the categories.
    // In general longer timeouts are better, because more data can be streamed at once.
    define('SYNC_TIMEOUT_MEDIUM_DEVICETYPES', "SAMSUNGGTI");
    define('SYNC_TIMEOUT_LONG_DEVICETYPES',   "iPod, iPad, iPhone, WP, WindowsOutlook");

make sure that WindowsOutlook is listed in long_devicetypes and as you can see in the log “Outlook” should be present too
(03/04/2018 20:19:59 [ 3296] [ INFO] [vincent@domein2.nl] cmd=‘Ping’ memory=‘2.44 MiB/2.00 MiB’ time=‘90.10s’ devType=‘Outlook’ devId=‘1ca749486aa9aebd’ getUser=‘vincent@domein2.nl\vincent@domein2.nl’ from=‘52.232.100.50’ idle=‘90s’ version=‘2.3.8+0’ method=‘POST’ httpcode=‘200’)

for the error with buffer cant be deleted, i got no clue, maybe an upgrade from 2.3.8 to z-push 2.3.9 will solve this. - you can try to complete resync the device and / or delete everything from phone/ourlook and from z-push

z-push-admin -a remove -u <username> -d <deviceID> 

deviceid can be obtained by 
z-push-admin -a list -u <username>

than run

z-push-admin -a clearloop
z-push-admin -a fixstates

and connect the device as a new device

the error in server.log, i need further information:
is kopano linked with activeDirectory
if yes, in /etc/kopano/ldap.cfg should be somethhing like:

# Optional, default = uid
# Active directory: sAMAccountName
# LDAP: uid
ldap_loginname_attribute = sAMAccountName

what does “id <username>” say, does it get your userinfo?
does it refere to uid or sAMAccountName? - check with ldapsearch (package openldap-clients) for uid and sAMAcountName

what does kopano-admin --details <username> say? does it get all properties?

//the loop detection is quite normal

for the spooler.log, check the log settings in spooler.cfg and incrase it to 5 (info) - and log_method = file

in the past i got a similar error, refering to postfix as it wont delete sended items from queue
check this behaviour aswell (if you are using postfix :) )
postqueue -p

regards,
coffee_is_life