[solved] kopano-server[]: setSyncStatus(): collision

umgfoin

My suspicion:
The message is triggered, as result of provider/libserver/cmd.cpp: SOAP_ENTRY_START(setSyncStatus, [...]) occasionally inserting empty sourcekey
-values into the syncs-table. Removing those entries cures the problem until new null-values are appearing. I’m trying to find out, when this happens.
++umgfoin.

fbartels

Thanks. I was able to observe the issue as well and created https://jira.kopano.io/browse/KC-1286 to further investigate.

umgfoin

Further findings:
the below call (exporter.Config(...) in ics.py produces sync-entries with empty sourcekeys:

def state(mapiobj, associated=False):
    exporter = mapiobj.OpenProperty(PR_CONTENTS_SYNCHRONIZER, IID_IExchangeExportChanges, 0, 0)
    if associated:
        exporter.Config(None, SYNC_NORMAL | SYNC_ASSOCIATED | SYNC_CATCHUP, None, None, None, None, 0)
    else:
        exporter.Config(None, SYNC_NORMAL | SYNC_CATCHUP, None, None, None, None, 0)

It’s getting called e.g. in service.py, line 180

class service::server(self)

_daemonize(self.main, options=self.options, log=self.log, config=self.config, service=self)

++umgfoin.

robgnu

Hello,
I can confirm this bug on a new Debian 9 installation.

Okt 09 06:14:11 kopano systemd[1]: Started Kopano Groupware Core Storage Server.
Okt 09 06:14:11 kopano kopano-server[1373]: Starting kopano-server version 8.6.81 (pid 1373 uid 0)
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for TCP connections on port 236
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for priority pipe connections on /var/run/kopano/prio.sock
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for pipe connections on /var/run/kopano/server.sock
Okt 09 06:14:11 kopano kopano-server[1373]: Coredumps are disabled via configuration file.
Okt 09 06:14:11 kopano kopano-server[1373]: Starting kopano-server version 8.6.81 (pid 1373 uid 999)
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for TCP connections on port 236
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for priority pipe connections on /var/run/kopano/prio.sock
Okt 09 06:14:11 kopano kopano-server[1373]: Listening for pipe connections on /var/run/kopano/server.sock
Okt 09 06:14:11 kopano kopano-server[1373]: Coredumps are disabled via configuration file.
Okt 09 06:14:11 kopano kopano-server[1373]: Connection to database 'kopano' succeeded
Okt 09 06:14:12 kopano kopano-server[1373]: Querying database for searchfolders. This may take a while.
Okt 09 06:14:12 kopano kopano-server[1373]: Loading search folders.
Okt 09 06:14:12 kopano kopano-server[1373]: Done loading search folders.
Okt 09 06:14:12 kopano kopano-server[1373]: Startup succeeded on pid 1373
Okt 09 06:14:12 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:17 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:22 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:27 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:32 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:37 kopano kopano-server[1373]: setSyncStatus(): collision
Okt 09 06:14:42 kopano kopano-server[1373]: setSyncStatus(): collision

I’m using nightly from 04.10.2018, but this problem seems to be present more than a month. (There was a nightly 8.6.81.228) with the same problem.)

robgnu.

Eric

@robgnu and others

To get rid of those annoing messages i stopped the search service and set search_enabled = no in server.cfg.

darootler

Hi,

i am using the following:

Ubuntu 18.04.1 LTS
Kopano 8.6.81

I am having the same troubles.

Regards
Richard

umgfoin

For me fixed with 39a7f6c2f7.

Thanks!
++umgfoin.

fbartels

Thanks for reporting back @umgfoin

Han

Hello,

I get this error after update Kopano-Core from v8.5.81.224 to 8.6.82.110
on Debian 9

I tried the workaround, which helps me last year:
1.) Stop all kopano services
2.) Remove all files from /var/lib/kopano/search/
3.) Start all services from kopano
After the new index files are done the error appear again.

Whats wrong?

Regards Han

fbartels

@han said in kopano-server[]: setSyncStatus(): collision:

to 8.6.82.110

please read the whole thread and then update to the latest available version.

Han

@Felix
thank you for the information.

I updated to the last available version 8.7.80.12 and get the same errors:

Tue Oct 30 16:55:26 2018: [error  ] Previous message logged 100 times
Tue Oct 30 16:55:26 2018: [error  ] setSyncStatus(): collision
Tue Oct 30 17:00:00 2018: [error  ] Previous message logged 54 times
Tue Oct 30 17:00:00 2018: [info   ] Start scheduled softdelete clean up
Tue Oct 30 17:00:00 2018: [info   ] Start to purge 2 messages
Tue Oct 30 17:00:01 2018: [info   ] Message purge done
Tue Oct 30 17:00:01 2018: [info   ] Softdelete done: removed 0 stores, 0 folders, and 2 messages
Tue Oct 30 17:00:02 2018: [error  ] setSyncStatus(): collision
Tue Oct 30 17:08:25 2018: [error  ] Previous message logged 100 times
Tue Oct 30 17:08:25 2018: [error  ] setSyncStatus(): collision
Tue Oct 30 17:13:01 2018: [error  ] Previous message logged 53 times
Tue Oct 30 17:13:01 2018: [info   ] Start syncs table clean up
Tue Oct 30 17:13:01 2018: [info   ] syncs table clean up done: removed syncs: 0
Tue Oct 30 17:13:01 2018: [error  ] setSyncStatus(): collision

Regards Han

fbartels

@Han I have not checked if it actually has been merged back to master, but there has been a new nightly release, so please try again.

tommi

Hi Felix,

version 8.7.80.27-0+22.1 solved it.

Greets Thomas

Han

Hello Felix,
after updae to 8.7.80.27 no errors setSyncStatus(): collision appaer,
but a lot of SQL errors like these:

Wed Oct 31 11:52:02 2018: [error  ] SQL [00000013] Failed: Duplicate entry '295398-26083-258' for key 'PRIMARY', Query Size: 343, Query: "INSERT INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(295398,26083,258,null,null,';▒▒C▒▒▒Hi▒▒▒\0',null,null,null,null),(295398,26082,258,null,null,';▒▒C▒▒▒Hi▒▒▒\0',null,null,null,null)"
Wed Oct 31 11:52:02 2018: [error  ] KDatabase::I_Update() query failed: "Duplicate entry '295398-26083-258' for key 'PRIMARY'", query: INSERT INTO properties (hierarchyid,tag,type,properties.val_ulong,properties.val_string,properties.val_binary,properties.val_double,properties.val_longint,properties.val_hi,properties.val_lo) VALUES(295398,26083,258,null,null,';▒▒C▒▒▒Hi▒▒▒\0',null,null,null,null),(295398,26082,258,null,null,';▒▒C▒▒▒Hi▒▒▒\0',null,null,null,null)

I think the update made my system work worse than before.
So I will roll back to the last state.

Regards
Han

tommi

Hello,

Yes, unfortunately the same here. It seems that every incoming mail generates the error.
Maybe open a new thread for this.

Regards
Thomas

fbartels

@tommi said in [solved] kopano-server[]: setSyncStatus(): collision:

Yes, unfortunately the same here. It seems that every incoming mail generates the error

Issue should be resolved with the packages that have just finished uploading.

umgfoin

@fbartels said in [solved] kopano-server[]: setSyncStatus(): collision:

Issue should be resolved with the packages that have just finished uploading.

Hi Felix,
no, still present in KC-master 31.10.2018 15:49 CET.

This issue is unrelated to the topic of this thread.
The problem came with recent refactorings in commit 0f8c99a3891, where ECRESULT AddChange(BTSession * ... uses the new infrastructure for std::list<propVal> based batch property-inserts.

Whereas the formerly called

ECRESULT WriteProp(ECDatabase *lpDatabase, unsigned int ulObjId, unsigned int ulParentId, struct propVal *lpPropVal, bool replace = true);

defined default parameter replace = true implementing REPLACE-queries for property writes, the now used

ECRESULT InsertProps(ECDatabase *lpDatabase, unsigned int ulObjId, unsigned int ulParentId, std::list<propVal> &propList);

treats all property-modifications as INSERT-queries, which is inappropriate to update an existing property.

for (auto &i : propList) {
		WriteSingleProp(database, objId, parentId, &i, false, 0, query, false);
		WriteSingleProp(database, objId, parentId, &i, true, 0, colquery, false);
}

Forcing InsertProps to create REPLACE -queries fixes the issue, but might have other implications.

WriteSingleProp(database, objId, parentId, &i, false, 0, query, true);
WriteSingleProp(database, objId, parentId, &i, true, 0, colquery, true);

++umgfoin.

deHoeninger

@umgfoin
I’m running into the same issue. It looks like Jelle van der Waa already addressed this issue with Commit https://stash.kopano.io/users/jvanderwaa/repos/kopanocore/commits/9df8d2c16613450d9662d99e27a0fe4b204be091

But it don’t found its way into Master yet.

Best Jan

umgfoin

Hi Jan,
it was merged into master, yesterday - so probably 'be part of the next community-build.
++umgfoin.

deHoeninger

@umgfoin said in [solved] kopano-server[]: setSyncStatus(): collision:

it was merged into master, yesterday - so probably 'be part of the next community-build.

Your are right, my fault. Should already be part of last nightly build.

Best Jan