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



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



  • Hi Felix,

    version 8.7.80.27-0+22.1 solved it.

    Greets Thomas



  • 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



  • Hello,

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

    Regards
    Thomas


  • Kopano

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


Log in to reply