[Bug] Buggy Sync of CalDav with Cozy

asked 2015-06-11 13:38:50 +0200

Hub
31 ●1 ●3 ●5

updated 2015-06-12 12:46:13 +0200

Hi everyone,

I've installed cozysoftware on a private server. Someone talk about it in this thread: https://together.jolla.com/question/84433/cozy-cloud-maybe-really-good-alternative-to-owncloud-if-elements-for-client-is-integrated/

I'm trying to sync my calendars from it to my Jolla. So for the moment, it's only Caldav.

I'm using a self-signed certificate so I checked "Ignore SSL errors" (I'm plan to use a real one but I just wanted to test first the sync in the first place)

Here the settings I've used:

• username: me
• password: XXXX
• Server address:https://cozy.mydomain.com/
• calendar path: /public/sync/calendars/me/Calendarname

The account is created, the authentification is working. I can see the name of my calendar in the option. But I have issue when I tried to sync the calendar. Only few entries are written into the DB.

When I sync, I have this log:

[root@Jolla ~]# journalctl -a -f | grep caldav
juin 11 11:58:19 Jolla estart[1702]: [W] Buteo::ProfileManagerPrivate::writeProfileFile:1153 - writeProfileFile()    called, forcing disk write: "/home/nemo/.cache/msyncd/sync/caldav-sync-49.xml" 
juin 11 11:58:19 Jolla [4863]: [W] Buteo::ProfileManagerPrivate::writeProfileFile:1153 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/caldav-sync-49.xml" 
juin 11 11:58:20 Jolla caldav-client[5157]: [W] Buteo::TransportTracker::btConnectivityStatus:202 - This device does not have a BT adapter 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::ConnectionManager::setupSocketConnection:106 - connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/100000/signond/socket: Aucun fichier ou dossier de ce type") 1 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::ConnectionManager::init:132 - connection-manager.cpp 132 init Peer connection unavailable, activating service 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingRegistration" SignOn::IdentityImpl(0x1bec480) 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::ConnectionManager::setupSocketConnection:106 - connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/100000/signond/socket: Aucun fichier ou dossier de ce type") 1 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::ConnectionManager::init:150 - connection-manager.cpp 150 init Connected to "qt_default_session_bus" 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0x1bec480) 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "NeedsUpdate" SignOn::IdentityImpl(0x1bec480) 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingUpdate" SignOn::IdentityImpl(0x1bec480) 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::infoUpdated:442 - identityimpl.cpp 442 infoUpdated SERVER INFO UPDATED. NeedsUpdate " 49 " 
juin 11 11:58:21 Jolla caldav-client[5157]: [W] mKCal::SqliteStorage::open:179 - sqlitestorage.cpp: 179 - database "/home/nemo/.local/share/system/privileged/Calendar/mkcal/db" opened 
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::getInfoReply:381 - identityimpl.cpp 381 getInfoReply QMap(("ACL", QVariant(QStringList, () ) ) ( "AuthMethods" ,  QVariant(QDBusArgument, ) ) ( "Caption" ,  QVariant(QString, "Jolla") ) ( "Id" ,  QVariant(uint, 49) ) ( "Owner" ,  QVariant(QStringList, () ) ) ( "Realms" ,  QVariant(QStringList, () ) ) ( "RefCount" ,  QVariant(int, 0) ) ( "StoreSecret" ,  QVariant(bool, true) ) ( "Type" ,  QVariant(int, 0) ) ( "UserName" ,  QVariant(QString, "me") ) ( "UserNameSecret" ,  QVariant(bool, false) ) ( "Validated" ,  QVariant(bool, true) ) )  
juin 11 11:58:21 Jolla caldav-client[5157]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0x1bec480) 
juin 11 11:58:39 Jolla caldav-client[5157]: [C] CalDavClient::notebookSyncFinished:544 - Notebook sync finished. Total agents: 1

From what I'm seeing, the syncronization went well but only the first few entries appears in my jolla calendar (which start around 2010).

When I query the database file (/home/nemo/.local/share/system/privileged/Calendars/db), I only see the first few entries:

[root@Jolla mkcal]# sqlite3 db
SQLite version 3.8.5 2014-06-04 14:06:34
Enter ".help" for usage hints.
sqlite> select * from Components;
[...] Events from birthday calendar
13|3705e7fd-608d-4f19-baae-2637e23d4722|Event|event1||1286748000|1286755200||0|1287180000|1287187200||0|0|||0|255.0|255.0|0||1434017476|1434017476|1434017476|0||||0|0|0|||urn:x-ical:94ada83a51a58bd5ac69e784b70087c1|94ada83a51a58bd5ac69e784b70087c1|0|0|0|0|0||0|||0
14|3705e7fd-608d-4f19-baae-2637e23d4722|Event|Event2||1287046800|1287054000|Europe/Paris|0|1287050400|1287057600|Europe/Paris|0|0|location||0|255.0|255.0|0||1434017476|1434017476|1434017476|0||||0|0|0|||urn:x-ical:94ada83a51a58bd5ac69e784b7008a0d|94ada83a51a58bd5ac69e784b7008a0d|0|0|0|0|0||0|||0

Only 2 entries are written whereas I've more than 200. I don't really know what's happening. I tried to delete the calendar DB several times, remove/recreate the account but always the same issue.

Edit: I tried with a calendar created from scratch with 7 entries. It is the same, only the first 2 are written into the DB.

Does anybody have an idea?

I'm using these versions:

• SailfishOS 1.1.4.29
• buteo-sync-plugin-carddav-0.0.9-1.4.1.armv7hl

Thanks.

[Edit]

By digging a little more, I think the issue is more about how the events are written into the database file more than a synchronization issue. Here an example:

I create an event from my jolla calendar and I set the calendar to be the one from my cozy application. In fact, it works very well! The event is written in the DB file and after synchronization, I can see it in my cozy apps!

So the main issue is the write of events from cozy calendar.

[Edit 2 12/06/2015]

After the comment of Chris, I increased the verbosity of the log. Here the results (I don't think the info here are sensitive, I didn't find either my domain or my password):

juin 12 11:02:03 Jolla estart[26865]: [W] Buteo::ProfileManagerPrivate::writeProfileFile:1153 - writeProfileFile() called, forcing disk write: "/home/nemo/.cache/msyncd/sync/caldav-sync-53.xml" 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] Buteo::USBModedProxy::isUSBConnected:85 - USB connected in mode:: "undefined" 
juin 12 11:02:04 Jolla caldav-client[1760]: [W] Buteo::TransportTracker::btConnectivityStatus:202 - This device does not have a BT adapter 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] Buteo::NetworkManager::NetworkManager:47 - Online status:: true 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] main:70 - attempting to register dbus service: "com.buteo.msyncd.plugin.caldav-sync-53" 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] main:77 - Plugin  "caldav"  with profile  "caldav-sync-53"  registered at dbus  "com.buteo.msyncd.plugin.caldav-sync-53"  and path  / 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] Buteo::ProfileManagerPrivate::ProfileManagerPrivate:126 - Primary profile path set to "/home/nemo/.cache/msyncd" 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] Buteo::ProfileManagerPrivate::ProfileManagerPrivate:127 - Secondary profile path set to "/etc/buteo/profiles" 
juin 12 11:02:04 Jolla caldav-client[1760]: [D] CalDavClient::initConfig:235 - Initiating config... 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::ConnectionManager::setupSocketConnection:106 - connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/100000/signond/socket: Aucun fichier ou dossier de ce type") 1 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::ConnectionManager::init:132 - connection-manager.cpp 132 init Peer connection unavailable, activating service 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingRegistration" SignOn::IdentityImpl(0xfd0040) 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] CalDavClient::startSync:116 - Init done. Continuing with sync 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::ConnectionManager::setupSocketConnection:106 - connection-manager.cpp 106 setupSocketConnection p2p error: QDBusError("org.freedesktop.DBus.Error.FileNotFound", "Failed to connect to socket /run/user/100000/signond/socket: Aucun fichier ou dossier de ce type") 1 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::ConnectionManager::init:150 - connection-manager.cpp 150 init Connected to "qt_default_session_bus" 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0xfd0040) 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "NeedsUpdate" SignOn::IdentityImpl(0xfd0040) 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingUpdate" SignOn::IdentityImpl(0xfd0040) 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::infoUpdated:442 - identityimpl.cpp 442 infoUpdated SERVER INFO UPDATED. NeedsUpdate " 53 " 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] AuthHandler::sessionResponse:137 - Authenticated! 
juin 12 11:02:05 Jolla caldav-client[1760]: [W] mKCal::SqliteStorage::open:179 - sqlitestorage.cpp: 179 - database "/home/nemo/.local/share/system/privileged/Calendar/mkcal/db" opened 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] CalDavClient::start:477 - ++++++++++++++ mSyncStartTime: QDateTime("2015-06-12 09:02:05.323 UTC Qt::UTC") LAST SYNC: QDateTime("2015-06-12 09:00:41.000 UTC Qt::UTC") 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] NotebookSyncAgent::startQuickSync:175 - Start quick sync for notebook: "0a469c78-6a16-454c-8ddf-006b7a51820c" between QDateTime("2014-12-12 09:02:05.323 UTC Qt::UTC") to QDateTime("2016-06-12 09:02:05.323 UTC Qt::UTC") , sync changes since QDateTime("2015-06-12 09:00:41.000 UTC Qt::UTC") 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] Request::debugRequest:139 - "---------------------------------------------------------------------
                                            <c:calendar-query xmlns:c="urn:ietf:params:xml:ns:caldav" xmlns:d="DAV:"><d:prop><d:getetag></d:getetag></d:prop><c:filter><c:comp-filter name="VCALENDAR"><c:comp-filter name="VEVENT"> <c:time-range end="20160612T090205Z" start="20141212T090205Z"></c:time-range></c:comp-filter></c:comp-filter></c:filter></c:calendar-query>
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::getInfoReply:381 - identityimpl.cpp 381 getInfoReply QMap(("ACL", QVariant(QStringList, () ) ) ( "AuthMethods" ,  QVariant(QDBusArgument, ) ) ( "Caption" ,  QVariant(QString, "Jolla") ) ( "Id" ,  QVariant(uint, 53) ) ( "Owner" ,  QVariant(QStringList, () ) ) ( "Realms" ,  QVariant(QStringList, () ) ) ( "RefCount" ,  QVariant(int, 0) ) ( "StoreSecret" ,  QVariant(bool, true) ) ( "Type" ,  QVariant(int, 0) ) ( "UserName" ,  QVariant(QString, "me") ) ( "UserNameSecret" ,  QVariant(bool, false) ) ( "Validated" ,  QVariant(bool, true) ) )  
juin 12 11:02:05 Jolla caldav-client[1760]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0xfd0040) 
juin 12 11:02:05 Jolla caldav-client[1760]: [D] Request::debugReplyAndReadAll:154 - "---------------------------------------------------------------------
juin 12 11:02:06 Jolla caldav-client[1760]: [D] Report::processResponse:155 - Process REPORT response for server path "/public/sync/calendars/me/coucou/" 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] Request::debugReply:149 - "---------------------------------------------------------------------
                                            REPORT response data:<d:multistatus xmlns:a="http://ajax.org/2005/aml" xmlns:cal="urn:ietf:params:xml:ns:caldav" xmlns:card="urn:ietf:params:xml:ns:carddav" xmlns:cs="http://calendarserver.org/ns/" xmlns:d="DAV:" xmlns:dav="urn:DAV"><d:response><d:href>/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b7133d1f.ics</d:href><d:propstat><d:prop><d:getetag>"ae295000e28e114bd137eee334970b3e"</d:getetag></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b713554a.ics</d:href><d:propstat><d:prop><d:getetag>"c733d143df143cd7e0999326595a06af"</d:getetag><d:resourcetype></d:resourcetype></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b7135f2d.ics</d:href><d:propstat><d:prop><d:getetag>"4a4b44952eecd6f2792c09b9193d2a42"</d:getetag><d:resourcetype></d:resourcetype></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b7136d29.ics</d:href><d:propstat><d:prop><d:getetag>"b5a1cf71b920bc1e213c950135075eea"</d:getetag><d:resourcetype></d:resourcetype></d:prop><d:status>HTTP/1.1 200 OK</d:status></d:propstat></d:response><d:response><d:href>/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69
juin 12 11:02:06 Jolla caldav-client[1760]: [D] Reader::readResponse:88 - "/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b7133d1f.ics" 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] Reader::readResponse:88 - "/public/sync/calendars/me/coucou/94ada83a51a58bd5ac69e784b713554a.ics" 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] NotebookSyncAgent::processETags:561 - Process tags for server path "/public/sync/calendars/me/coucou/" 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] NotebookSyncAgent::processETags:595 - Fetching new incidences: () 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] NotebookSyncAgent::loadLocalChanges:359 - Initially found changes for "/public/sync/calendars/me/coucou/" since QDateTime("2015-06-12 09:00:41.000 UTC Qt::UTC") : inserted =  0 modified =  0 deleted =  0 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] NotebookSyncAgent::sendLocalChanges:279 - No changes to send! 
juin 12 11:02:06 Jolla caldav-client[1760]: [C] CalDavClient::notebookSyncFinished:544 - Notebook sync finished. Total agents: 1 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] NotebookSyncAgent::finalize:228 - Writing 0 insertions, 0 modifications 0 deletions 0 updated etags 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] CalDavClient::notebookSyncFinished:571 - Any database changes to write? (including clearing of entries) true 
juin 12 11:02:06 Jolla caldav-client[1760]: [D] CalDavClient::syncFinished:328 - CalDAV sync succeeded! "" 
</d:href></d:response></d:multistatus> 

Here, I created a test calendar called coucou with 7 entries (cozy1 to cozy7) with a range date between 13 June 2015 to 25 June 2015. Only the first 2 entries are written in the DB file.

From the log and from what I understand, we can see the authentification is working and it connects to the calendar. But the REPORT response data line is quite interesting. It fetches the entries of my calendar but only 4 of them. The entries are correct (the downloaded ics file from the path is valid) and correspond to my created events.

Furthermore, there is only 2 lines Reader::readResponse:88 with a path to the events. This 2 paths correspond to the 2 events that are correctly written in the DB file.

It will really help if someone with a Jolla/Cozy duo can reproduce it.