Sync fails because of "Couldn't unbind CustomCertService"

[cjeudico]

Hi there.

I have run into a problem with 2.0.5-ose installed from F-Droid.

I have done the following steps:

1. Ran DAVdroid < 2.0.5-ose (don’t remember the version) for years with a self-hosted Baikal instance.
2. Turned off the Baikal instance.
3. Exported all calendars to .ics-files using the app “Calendar Import Export”
4. Removed DAVdroid from phone
5. Created an account at posteo.de
6. Installed DAVdroid 2.0.5-ose on phone
7. Created calendars on posteo.de
8. Logged into posteo.de account in DAVdroid 2.0.5-ose
9. Set all sync intervalls to 60 minutes and set to sync all past events
10. Enabled logging to external file
11. Imported .ics-File with about 1300 entries to a posteo.de calendar using the app “Calendar Import Export”.
12. Start a sync in DAVdroid settings
13. Wait
14. No events appear in posteo.de web interface
15. Look inside external log file.
16. Find the following entries in the log file (see end of post). (I have anonymized the log and removed a lot of info. I am happy to submit the full anonymized file via a private message or the likes):
17. Remove DAVdroid 2.0.5-ose and install DAVdroid 2.0.3-ose
18. Remove all calendars in posteo.de
19. Redo steps 7-13 with DAVdroid 2.0.3-ose
20. Events appear in posteo.de and are synced properly.

Unfortunately I won’t be able to test further, because 2.0.3-ose is working and I don’t want to mess with the now working setup.

I’m curious to hear your thoughts.

Thanks for the great work, btw, I appreciate it!

Log file of DAVdroid 2.0.5-ose:

2018-11-14 22:52:18 4747 [AndroidEvent] Read event entity from calender provider
	PARAMETER #0 = availability=0 dtstart=1498867200000 lastSynced=0 duration=P1D rrule=FREQ=MONTHLY accessLevel=0 eventTimezone=UTC allDay=1 hasAttendeeData=0 _id=9273 guestsCanModify=1 uid2445=87ac2b81-7389-493a-9746-e5db77a685aa dirty=1 guestsCanInviteOthers=1 cal_sync1={"type":"CTAG","value":"0"} guestsCanSeeGuests=1 selfAttendeeStatus=0 mutators=org.sufficientlysecure.ical hasExtendedProperties=0 organizer=<anonymized> title=<anynomized> calendar_id=3 deleted=0 hasAlarm=0 isOrganizer=0



<removed tons of entries "Read event entity from calender provider">


2018-11-14 22:53:20 4747 [AndroidEvent] Read event entity from calender provider
	PARAMETER #0 = availability=0 dtstart=1479378600000 lastSynced=0 accessLevel=0 eventTimezone=Europe/Paris allDay=0 dtend=1479384000000 hasAttendeeData=0 _id=9869 guestsCanModify=1 uid2445=8d8ef415-a999-4595-a2df-1c1cfe1b9cfe dirty=1 guestsCanInviteOthers=1 lastDate=1479384000000 cal_sync1={"type":"CTAG","value":"0"} guestsCanSeeGuests=1 eventEndTimezone=Europe/Paris selfAttendeeStatus=0 mutators=org.sufficientlysecure.ical hasExtendedProperties=0 organizer=<anonymized> title=<anonymized> calendar_id=3 deleted=0 hasAlarm=0 isOrganizer=0
2018-11-14 22:53:20 4747 [CustomCertManager] Couldn't unbind CustomCertService
EXCEPTION java.lang.IllegalArgumentException: Service not registered: at.bitfire.cert4android.CustomCertManager$1@4effc3c
	at android.app.LoadedApk.forgetServiceDispatcher(LoadedApk.java:1289)
	at android.app.ContextImpl.unbindService(ContextImpl.java:1483)
	at android.content.ContextWrapper.unbindService(ContextWrapper.java:648)
	at at.bitfire.cert4android.CustomCertManager.close(CustomCertManager.kt:115)
	at at.bitfire.davdroid.HttpClient.close(HttpClient.kt:65)
	at at.bitfire.davdroid.syncadapter.SyncManager.close(SyncManager.kt:101)
	at kotlin.jdk7.AutoCloseableKt.closeFinally(AutoCloseable.kt:59)
	at at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService$CalendarsSyncAdapter.sync(CalendarsSyncAdapterService.kt:55)
	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:84)
	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:272)

2018-11-14 22:53:20 4747 [syncadapter.CalendarsSyncAdapterService] Couldn't sync calendars
EXCEPTION java.lang.InterruptedException: Sync was cancelled
	at at.bitfire.davdroid.syncadapter.SyncManager.abortIfCancelled(SyncManager.kt:588)
	at at.bitfire.davdroid.syncadapter.SyncManager$uploadDirty$1.invoke(SyncManager.kt:302)
	at at.bitfire.davdroid.syncadapter.SyncManager$uploadDirty$1.invoke(SyncManager.kt:55)
	at at.bitfire.davdroid.syncadapter.SyncManager.useLocal(SyncManager.kt:760)
	at at.bitfire.davdroid.syncadapter.SyncManager.uploadDirty(SyncManager.kt:301)
	at at.bitfire.davdroid.syncadapter.SyncManager$performSync$1.invoke(SyncManager.kt:123)
	at at.bitfire.davdroid.syncadapter.SyncManager$performSync$1.invoke(SyncManager.kt:55)
	at at.bitfire.davdroid.syncadapter.SyncManager.unwrapExceptions(SyncManager.kt:800)
	at at.bitfire.davdroid.syncadapter.SyncManager.performSync(SyncManager.kt:109)
	at at.bitfire.davdroid.syncadapter.CalendarsSyncAdapterService$CalendarsSyncAdapter.sync(CalendarsSyncAdapterService.kt:56)
	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:84)
	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:272)

2018-11-14 22:53:20 4747 [syncadapter.CalendarsSyncAdapterService] Calendar sync complete
2018-11-14 22:53:20 4747 [settings.Settings] Couldn't unbind Settings service
EXCEPTION java.lang.IllegalArgumentException: Service not registered: at.bitfire.davdroid.settings.Settings$Companion$getInstance$serviceConn$1@af48b6a
	at android.app.LoadedApk.forgetServiceDispatcher(LoadedApk.java:1289)
	at android.app.ContextImpl.unbindService(ContextImpl.java:1483)
	at android.content.ContextWrapper.unbindService(ContextWrapper.java:648)
	at at.bitfire.davdroid.settings.Settings$Stub.close(Settings.kt:223)
	at kotlin.jdk7.AutoCloseableKt.closeFinally(AutoCloseable.kt:56)
	at at.bitfire.davdroid.syncadapter.SyncAdapterService$SyncAdapter.onPerformSync(SyncAdapterService.kt:75)
	at android.content.AbstractThreadedSyncAdapter$SyncThread.run(AbstractThreadedSyncAdapter.java:272)

2018-11-14 22:53:20 4747 [syncadapter.SyncAdapterService] Sync for (com.android.calendar, Account {name=<anonymized>@posteo.de, type=bitfire.at.davdroid}) finished```

[cjeudico]

Update:
I have now run into the same issue on 2.0.3-ose!
The sync ends with the message " Couldn’t unbind CustomCertService"

Does not seem to be a bug that was introduced between 2.0.3-ose and 2.0.5-ose.

[cjeudico]

Debug log for 2.0.3-ose is:

--- BEGIN DEBUG INFO ---

SOFTWARE INFORMATION
Package: at.bitfire.davdroid
Version: 2.0.3-ose (244) from Aug 30, 2018
Installed from: com.android.packageinstaller
JB Workaround installed: no

CONNECTIVITY (at the moment)
Active connection: WiFi, CONNECTED

CONFIGURATION
Power saving disabled: yes
android.permission.READ_CONTACTS permission: denied
android.permission.WRITE_CONTACTS permission: denied
android.permission.READ_CALENDAR permission: granted
android.permission.WRITE_CALENDAR permission: granted
org.dmfs.permission.READ_TASKS permission: granted
org.dmfs.permission.WRITE_TASKS permission: granted
System-wide synchronization: automatically
Account: <anonymized>@<anonymized>
  Address book sync. interval: 60 min
  Calendar     sync. interval: 60 min
  OpenTasks    sync. interval: 60 min
  WiFi only: false
  [CardDAV] Contact group method: CATEGORIES
  [CalDAV] Time range (past days): null
           Manage calendar colors: true

SQLITE DUMP
android_metadata
	|  locale |
	|  en_US |
----------
services
	|  _id | accountName | service | principal |
	|  1 | <anonymized>@<anonymized> | carddav | https://posteo.de:8443/principals/<anonymized><anonymized>/ |
	|  2 | <anonymized>@<anonymized> | caldav | https://posteo.de:8443/principals/<anonymized><anonymized>/ |
----------
sqlite_sequence
	|  name | seq |
	|  services | 2 |
	|  homesets | 2 |
	|  collections | 3 |
----------
homesets
	|  _id | serviceID | url |
	|  1 | 1 | https://posteo.de:8443/addressbooks/<anonymized><anonymized>/ |
	|  2 | 2 | https://posteo.de:8443/calendars/<anonymized><anonymized>/ |
----------
collections
	|  _id | serviceID | type | url | privWriteContent | privUnbind | forceReadOnly | displayName | description | color | timezone | supportsVEVENT | supportsVTODO | source | sync |
	|  1 | 1 | ADDRESS_BOOK | https://posteo.de:8443/addressbooks/<anonymized><anonymized>/default/ | 1 | 1 | 0 | default addressbook | <null> | <null> | <null> | 0 | 0 | <null> | 0 |
	|  2 | 2 | CALENDAR | https://posteo.de:8443/calendars/<anonymized><anonymized>/default/ | 1 | 1 | 0 | nicht benutzt | <null> | -5717279 | <null> | 1 | 1 | <null> | 0 |
	|  3 | 2 | CALENDAR | https://posteo.de:8443/calendars/<anonymized><anonymized>/htszvo/ | 1 | 1 | 0 | Persönlich | <null> | -5717279 | <null> | 1 | 1 | <null> | 1 |
----------

SYSTEM INFORMATION
Android version: 7.1.2 (lineage_athene-userdebug 7.1.2 NJH47F 3fbfe6998a)
Device: Motorola Moto G4 (athene)

--- END DEBUG INFO ---

[cjeudico]

I can import the .ics-file to a local Thunderbird calendar without problems.

If I create a posteo.de CalDav calendar in Thunderbird and then import the .ics-file, the import fails for 51 entries.
So it seems like the problem is not related to DAVdroid but to posteo.de or my .ics-file.

However the error message DAVdroid produces is not very helpful

[cjeudico]

I’ve been able to figure out why the import in Thunderbird failed for the 51 entries:

If the UID of a VEVENT contains “@domainname.tld” or “@machine-name”, the Posteo.de CalDAV server returns HTTP statuscode 404 for the REPORT HTTP method.

I have now removed all occurences of “@followedbyastring” and successfully imported my .ics-file with Thunderbird.

I have not tested the import on my phone using DAVdroid and Calendar Import Export.

Should Posteo.de support occurences of “@followedbyastring” in a UID?

If I have time to do so, I will report this issue to Posteo.de
But please: Feel free to test and report the issue to Posteo.de

Sorry for the noise, I initially thought this was a DAVdroid problem.