kopano-server[]: setSyncStatus(): collision

Hi,
after upgrade i get every 5 Sekonds

kopano-server[]: setSyncStatus(): collision

Version 8.6.81

I tried

service kopano-server stop
kopano-server --restart-searches

Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 32
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 68495
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 171603
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 198616
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 214408
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 224928
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 226637
Sep 24 09:10:21 mail kopano-server[7237]:   Rebuilding searchfolders of store 233508
Se

But after Restart kopano-server the same.

It seams that kopano is running.

Greets
Thomas

Hi, same error here with a new installation (also 8.6.81) on Debian.

● kopano-server.service - Kopano Groupware Core Storage Server
Loaded: loaded (/lib/systemd/system/kopano-server.service; disabled; vendor p
Active: active (running) since Mon 2018-09-24 12:00:02 CEST; 46min ago
Docs: man:kopano-server(8)
man:kopano-server.cfg(5)
man:kopano-admin(8)
Main PID: 21298 (kopano-server)
Tasks: 21 (limit: 4915)
CGroup: /system.slice/kopano-server.service
└─21298 /usr/sbin/kopano-server -F

Sep 24 12:45:46 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:45:51 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:45:56 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:01 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:06 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:11 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:16 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:21 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:26 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision
Sep 24 12:46:31 xxxxxxxx kopano-server[21298]: setSyncStatus(): collision

Did over the installation different times, different config parameters, nothing helps.
No other errors.

Any help?

Eric

Hi @tommi and @Eric ,

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

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

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

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

@fbartels

Hi Felix,

Same version as Thomas : 8.6.81.228-0+37.1

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

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.

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

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.

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.

@robgnu and others

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

Hi,

i am using the following:

Ubuntu 18.04.1 LTS
Kopano 8.6.81

I am having the same troubles.

Regards
Richard