[solved] 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


  • Kopano

    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


  • Kopano

    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.


  • Kopano

    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



  • For me fixed with 39a7f6c2f7.

    Thanks!
    ++umgfoin.


  • Kopano

    Thanks for reporting back @umgfoin



  • 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


  • Kopano

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



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


  • Kopano

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


Log in to reply