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

fbartels

can you specify which exact version of Kopano you are using (so for example by posting the result of dpkg -l | grep kopano-server?

tommi

Hi Felix,
Version kopano-server 8.6.81.228-0+37.1

umgfoin

Same with 8.6.81.396 (current master 1fd7b2eb398).

Mon Sep 24 16:24:41 2018: [info   ] Audit logging not enabled.
Mon Sep 24 16:24:41 2018: [=======] Starting kopano-server version 8.6.81.396 (pid 19470 uid 0)
Mon Sep 24 16:24:41 2018: [info   ] Using epoll events
Mon Sep 24 16:24:41 2018: [notice ] Listening for TCP connections on port 236
Mon Sep 24 16:24:41 2018: [notice ] Listening for priority pipe connections on /var/run/kopano/prio.sock
Mon Sep 24 16:24:41 2018: [notice ] Listening for pipe connections on /var/run/kopano/server.sock
Mon Sep 24 16:24:41 2018: [debug  ] Reexecing /usr/sbin/kopano-server
Mon Sep 24 16:24:41 2018: [info   ] Audit logging not enabled.
Mon Sep 24 16:24:41 2018: [=======] Starting kopano-server version 8.6.81.396 (pid 19470 uid 378)
Mon Sep 24 16:24:41 2018: [info   ] Using epoll events
Mon Sep 24 16:24:41 2018: [notice ] Listening for TCP connections on port 236
Mon Sep 24 16:24:41 2018: [notice ] Listening for priority pipe connections on /var/run/kopano/prio.sock
Mon Sep 24 16:24:41 2018: [notice ] Listening for pipe connections on /var/run/kopano/server.sock
Mon Sep 24 16:24:41 2018: [notice ] Connection to database 'kdb' succeeded
Mon Sep 24 16:24:41 2018: [debug  ] PurgeCache took 0 ms
Mon Sep 24 16:24:41 2018: [notice ] Querying database for searchfolders. This may take a while.
Mon Sep 24 16:24:41 2018: [notice ] Loading search folders.
Mon Sep 24 16:24:41 2018: [notice ] Done loading search folders.
Mon Sep 24 16:24:41 2018: [notice ] Startup succeeded on pid 19474
Mon Sep 24 16:24:41 2018: [debug  ] Accepted incoming connection from file:///var/run/kopano/server.sock
Mon Sep 24 16:24:46 2018: [debug  ] Previous message logged 16 times
Mon Sep 24 16:24:46 2018: [error  ] setSyncStatus(): collision
Mon Sep 24 16:24:51 2018: [debug  ] Accepted incoming connection from file:///var/run/kopano/server.sock
Mon Sep 24 16:24:51 2018: [error  ] setSyncStatus(): collision
Mon Sep 24 16:25:22 2018: [error  ] Previous message logged 6 times
Mon Sep 24 16:25:22 2018: [debug  ] Accepted incoming connection from file:///var/run/kopano/server.sock
Mon Sep 24 16:25:26 2018: [error  ] setSyncStatus(): collision
Mon Sep 24 16:25:53 2018: [error  ] Previous message logged 5 times
Mon Sep 24 16:25:53 2018: [debug  ] Accepted incoming connection from file:///var/run/kopano/server.sock
Mon Sep 24 16:25:56 2018: [error  ] setSyncStatus(): collision
Mon Sep 24 16:26:11 2018: [error  ] Previous message logged 2 times
Mon Sep 24 16:26:11 2018: [debug  ] Accepted incoming connection from file:///var/run/kopano/server.sock
Mon Sep 24 16:26:11 2018: [error  ] setSyncStatus(): collision

++umgfoin

fbartels

Thanks. What was the last version for you that did log this message?

Eric

@fbartels

Hi Felix,

Same version as Thomas : 8.6.81.228-0+37.1

Vogi

I am expierencing the same error message.
I am using git master - last update was 5 day ago (git commit cf1b6a39095a4431d77ff1db7eeb70650db52efc) - there the beahviour is already included

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