Inital CalDAV sync fails on Jolla C due to annually recurring event

asked 2016-08-27 17:06:35 +0200

Benjamin gravatar image

Since I got my Jolla C, I cannot use my CalDAV calendars, because the initial synchronization fails. When triggering the sync, I see that the calendars appear for a very short time (< 1 s) in the calendar application, but then disappear again. In the settings page for the CalDAV account, I see that the remote calendars are listed. I tried using two separate accounts for CalDAV and CardDAV and also one combined account. The same calendars worked on my Jolla 1. I am now using the early access release 2.0.2.48. I have buteo-sync-plugin-caldav in version 0.1.34-1.20.1. I am using ownCloud 9.0.4 (stable) on the server. I have obtained a log following the description in another question. I see that the sync always fails for a specific event:

Aug 06 12:57:56 Sailfish caldav-client[5314]: [C] NotebookSyncAgent::updateIncidence:1303 - Unable to add incidence "NBUID:d2eaa307-a881-4ba1-8a35-12acdb303a6f:7d145c8e-0f34-45a0-b8ca-d9c86093bc11" "" to notebook "d2eaa307-a881-4ba1-8a35-12acdb303a6f" 
Aug 06 12:57:56 Sailfish caldav-client[5314]: [W] NotebookSyncAgent::updateIncidences:1403 - Error saving base incidence of resource "/remote.php/dav/calendars/[myusername]/[mycalendarname]/7d145c8e-0f34-45a0-b8ca-d9c86093bc11.ics" 
Aug 06 12:57:56 Sailfish caldav-client[5314]: [C] CalDavClient::syncFinished:370 - CalDAV sync failed: 401 "unable to write notebook changes"

I downloaded that event from the URL mentioned in the log (I censored the summary and categories):

BEGIN:VCALENDAR
PRODID:-//K Desktop Environment//NONSGML libkcal 4.3//EN
VERSION:2.0
X-KDE-ICAL-IMPLEMENTATION-VERSION:1.0
BEGIN:VEVENT
DTSTAMP:20160524T190438Z
CREATED:20160520T195542Z
UID:7d145c8e-0f34-45a0-b8ca-d9c86093bc11
SEQUENCE:1
LAST-MODIFIED:20160524T190438Z
SUMMARY:My Event
CATEGORIES:CatA,CatB,Persönlich
RRULE:FREQ=YEARLY;BYMONTHDAY=9;BYMONTH=11
DTSTART;VALUE=DATE:20121109
DTEND;VALUE=DATE:20121110
TRANSP:TRANSPARENT
END:VEVENT
END:VCALENDAR
edit retag flag offensive close delete

Comments

Thanks for this information. I've created a bug report: https://bugs.merproject.org/show_bug.cgi?id=1646 to track it.

If you (or someone who reads this) is interested in helping to fix bugs in the CalDAV plugin, please note that there is a topic about this in the SailfishOS Community Meeting tonight, in #mer-meetings on Freenode IRC.

chris.adams ( 2016-09-05 05:48:48 +0200 )edit

Thanks for forwarding the information to the bug tracker. One general suggestion/question: Why does the whole sync fail, if a single event cannot be parsed or saved? In my opinion it would make sense to skip and ignore that event and continue with the remaining ones. I would prefer a calendar with a few missing events (inform the user about them) to no calendar at all.

Benjamin ( 2016-09-06 23:51:57 +0200 )edit

I agree. The short answer is that we haven't implemented per-event synchronisation yet. We should fall back to it if the entire mass-sync cycle fails, I think, but there's non-trivial effort required to support this feature. (And mass-sync needs to be the default for performance and stability reasons; much better to do a large amount of database commits within a single transaction, than to have a single transaction per commit.)

Please see https://sailfishos.org/wiki/CalDAV_and_CardDAV_Community_Contributions if you're willing to help with the development of the single-event-at-a-time-sync fallback feature.

chris.adams ( 2016-09-08 12:04:54 +0200 )edit

Hi, one of the community members did some further investigation into this issue, and there are a couple of potential leads which he is following up on (see the discussion in the bug report). One quick question (just to cross off the simplest - but least likely - explanation off the list): are there any duplicated UIDs being returned by the server in the per-calendar event listing report request?

chris.adams ( 2016-09-26 04:08:10 +0200 )edit

@chris.adams: I do not see any duplicated UIDs in the log. Here you have the full log (I censored some names):

Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::USBModedProxy::isUSBConnected:85 - USB connected in mode:: "undefined" 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::TransportTracker::btConnectivityStatus:237 - Bluetooth powered on?  false 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::NetworkManager::NetworkManager:74 - Online status:: true 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] main:71 - attempting to register dbus service: "com.buteo.msyncd.plugin.caldav-sync-7" 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] main:78 - Plugin  "caldav"  with profile  "caldav-sync-7"  registered at dbus  "com.buteo.msyncd.plugin.caldav-sync-7"  and path  / 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::ProfileManagerPrivate::ProfileManagerPrivate:126 - Primary profile path set to "/home/nemo/.cache/msyncd" 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::ProfileManagerPrivate::ProfileManagerPrivate:127 - Secondary profile path set to "/etc/buteo/profiles" 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::ProfileManager::syncProfile:359 - ProfileManager::syncProfile( "caldav-sync-7" ) 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] Buteo::ProfileManager::syncProfile:364 - found a valid sync profile with the given name: "caldav-sync-7" 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] CalDavClient::initConfig:279 - Initiating config... 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [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: No such file or directory") 1 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] SignOn::ConnectionManager::init:132 - connection-manager.cpp 132 init Peer connection unavailable, activating service 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingRegistration" SignOn::IdentityImpl(0xb514e8) 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] SignOn::AuthSessionImpl::initInterface:94 - authsessionimpl.cpp 94 initInterface 
Oct 01 11:25:05 Sailfish caldav-client[10796]: [D] CalDavClient::startSync:112 - Init done. Continuing with sync 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::ConnectionManager::init:150 - connection-manager.cpp 150 init Connected to "libsignon-qt1" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0xb514e8) 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "NeedsUpdate" SignOn::IdentityImpl(0xb514e8) 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "PendingUpdate" SignOn::IdentityImpl(0xb514e8) 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::infoUpdated:442 - identityimpl.cpp 442 infoUpdated SERVER INFO UPDATED. NeedsUpdate " 7 " 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] AuthHandler::sessionResponse:142 - Authenticated! 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [W] mKCal::SqliteStorage::open:193 - sqlitestorage.cpp: 193 - database "/home/nemo/.local/share/system/privileged/Calendar/mkcal/db" opened 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] CalDavClient::start:460 - ++++++++++++++ mSyncStartTime: QDateTime(" Qt::LocalTime") LAST SYNC: QDateTime(" Qt::LocalTime") 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] CalDavClient::start:504 - no notebook exists for calendar path: "/remote.php/dav/calendars/benjamin/privatbenjamin/" , creating new 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] CalDavClient::start:505 - performing slow sync for "/remote.php/dav/calendars/benjamin/privatbenjamin/" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] NotebookSyncAgent::startSlowSync:215 - Start slow sync for notebook: "Privat Benjamin" for account "7" between QDateTime("2016-04-01 09:25:06.188 UTC Qt::UTC") to QDateTime("2017-10-01 09:25:06.188 UTC Qt::UTC") 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "---------------------------------------------------------------------" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Depth : 1" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Prefer : return-minimal" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Content-Length : 321"                                                                                                               
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Content-Type : application/xml; charset=utf-8"                                                                                      
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "URL = https://user:pass@my.server.com/remote.php/dav/calendars/benjamin/privatbenjamin/"                                       
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Request : REPORT"                                                                                                                   
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "<c:calendar-query xmlns:c="urn:ietf:params:xml:ns:caldav" xmlns:d="DAV:"><d:prop><d:getetag><c:calendar-data></c:calendar-data></d:getetag></d:prop><c:filter><c:comp-filter name="VCALENDAR"><c:comp-filter name="VEVENT"> <c:time-range end="20171001T092506Z" start="20160401T092506Z"></c:time-range></c:comp-filter></c:comp-filter></c:filter></c:calendar-query>"                      
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "---------------------------------------------------------------------" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] CalDavClient::start:504 - no notebook exists for calendar path: "/remote.php/dav/calendars/benjamin/secondcal_shared_by_someoneelse/" , creating new 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] CalDavClient::start:505 - performing slow sync for "/remote.php/dav/calendars/benjamin/secondcal_shared_by_someoneelse/" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] NotebookSyncAgent::startSlowSync:215 - Start slow sync for notebook: "secondcal(someoneelse)" for account "7" between QDateTime("2016-04-01 09:25:06.188 UTC Qt::UTC") to QDateTime("2017-10-01 09:25:06.188 UTC Qt::UTC") 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "---------------------------------------------------------------------" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Depth : 1" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Prefer : return-minimal" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Content-Length : 321" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Content-Type : application/xml; charset=utf-8" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "URL = https://user:pass@my.server.com/remote.php/dav/calendars/benjamin/secondcal_shared_by_someoneelse/" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "Request : REPORT" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "<c:calendar-query xmlns:c="urn:ietf:params:xml:ns:caldav" xmlns:d="DAV:"><d:prop><d:getetag><c:calendar-data></c:calendar-data></d:getetag></d:prop><c:filter><c:comp-filter name="VCALENDAR"><c:comp-filter name="VEVENT"> <c:time-range end="20171001T092506Z" start="20160401T092506Z"></c:time-range></c:comp-filter></c:comp-filter></c:filter></c:calendar-query>" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] Request::debugRequest:140 - "---------------------------------------------------------------------" 
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::getInfoReply:381 - identityimpl.cpp 381 getInfoReply QMap(("ACL", QVariant(QStringList, () ) ) ( "AuthMethods" ,  QVariant(QDBusArgument, ) ) ( "Caption" ,  QVariant(QString, "Jolla") ) ( "Id" ,  QVariant(uint, 7) ) ( "Owner" ,  QVariant(QStringList, () ) ) ( "Realms" ,  QVariant(QStringList, () ) ) ( "RefCount" ,  QVariant(int, 0) ) ( "StoreSecret" ,  QVariant(bool, true) ) ( "Type" ,  QVariant(int, 0) ) ( "UserName" ,  QVariant(QString, "benjamin") ) ( "UserNameSecret" ,  QVariant(bool, false) ) ( "Validated" ,  QVariant(bool, true) ) )  
Oct 01 11:25:06 Sailfish caldav-client[10796]: [D] SignOn::IdentityImpl::updateState:96 - identityimpl.cpp 96 updateState Updating state:  "Ready" SignOn::IdentityImpl(0xb514e8) 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Report::processResponse:155 - Process REPORT response for server path "/remote.php/dav/calendars/benjamin/privatbenjamin/" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "---------------------------------------------------------------------" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "REPORT response status code: 207" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "REPORT response headers:" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Date : Sat, 01 Oct 2016 09:25:05 GMT" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Server : Apache" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Expires : Thu, 19 Nov 1981 08:52:00 GMT" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Cache-Control : no-store, no-cache, must-revalidate, post-check=0, pre-check=0" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Pragma : no-cache" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Content-Security-Policy : default-src 'self'; script-src 'self' 'unsafe-eval'; style-src 'self' 'unsafe-inline'; frame-src *; img-src * data: blob:; font-src 'self' data:; media-src *; connect-src *" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-XSS-Protection : 1; mode=block" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Content-Type-Options : nosniff" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Frame-Options : Sameorigin" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Robots-Tag : none" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Download-Options : noopen" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Permitted-Cross-Domain-Policies : none" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Vary : Brief,Prefer" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Set-Cookie : oc_sessionPassphrase=xyzXYZUGkM%2BWRZkRlCkvOYXdq%2FYbyhLABcXyZLul0h6JYoJszsuZZzpBGWyJezQSl1tgrABCKnedXIouf05R1Cwf2jFbOW3qPsk4XUJ9Nqw8J%2BExyzzOI5GueP00TQLy; path=/; secure; httponly" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "50af8234576a4=31crabcfsa0ddkabc1gii8a113; path=/; secure; HttpOnly" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  X-Powered-By : PleskLin" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Keep-Alive : timeout=5, max=99" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Connection : Keep-Alive" 
Oct 01 11:25:07 Sailfish caldav-client[10796]: [D] Request::debugReply:154 - "  Transfer-Encoding : chunked" 
Oct 01 11:25:14 Sailfish caldav-client[10796]: [C] NotebookSyncAgent::updateIncidence:1303 - Unable to add incidence "NBUID:ff1f618c-2e24-44fe-b24d-72f593886830:7d145c8e-0f34-45a0-b8ca-d9c86093bc11" "" to notebook "ff1f618c-2e24-44fe-b24d-72f593886830" 
Oct 01 11:25:14 Sailfish caldav-client[10796]: [W] NotebookSyncAgent::updateIncidences:1403 - Error saving base incidence of resource "/remote.php/dav/calendars/benjamin/privatbenjamin/7d145c8e-0f34-45a0-b8ca-d9c86093bc11.ics" 
Oct 01 11:25:14 Sailfish caldav-client[10796]: [C] CalDavClient::syncFinished:370 - CalDAV sync failed: 401 "unable to write notebook changes"
Benjamin ( 2016-10-01 12:38:20 +0200 )edit