We have a problem with the Caldav binding: There are two calendars installed in the config file (commandCal and privateCal). When I install Caldav Command and Caldav Personal, I receive a promising message:
CalDAV IO is properly configured.
2018-01-04 10:11:05.617 [INFO ] [b.core.service.AbstractActiveService] - CalDav Loader has been started
2018-01-04 10:11:05.659 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - reload job scheduled for: privatCal
2018-01-04 10:11:05.663 [INFO ] [.io.caldav.internal.CalDavLoaderImpl] - reload job scheduled for: commandCal
The events oft he personal Calendar are loaded ok, e.g. „2018-01-04 10:13:43.877 [ome.event.ItemCommandEvent] - Item ‘Calendar_NameTime1’ received command Sport @ 05.01.2018: 13:00-16:00“
But events which should be actually executed, just produce an info saying that the event begins.
E.g.: 2018-01-04 10:11:25.776 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 173e151513dd311af4a4952161af7606-LWSDpcj(New2@04.01.2018/09:52-04.01.2018/10:54)
But nothing happens, although I have the command in the message body.
Yesterday I had a running version but changed calendars and uninstalled/installed both caldav bindings again. That was a big mistake. I now have yesterdays settings restored and the cache content etc. deleted but still have the problem that the events are read but not executed.
Any idea what I can try in addition?
PS: I just found the commands in my old log, when it worked. Here I have the “Sending command” that never comes up although the command is now the same "BEGIN:Billy_r4F_AZ:ON"
2018-01-03 12:10:00.009 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 840a48d863140af244aba8d0e26e8313-eiAfJmW(Billy@03.01.2018/12:10-03.01.2018/12:15)
2018-01-03 12:10:00.079 [INFO ] [aldav_command.internal.CalDavBinding] - sending command ‘ON’ to item ‘Billy_r4F_AZ’ from event ‘840a48d863140af244aba8d0e26e8313-eiAfJmW(Billy@03.01.2018/12:10-03.01.2018/12:15)’
I have turned on debug mode for the personal and the command binding as well as for caldavio. I do not see any warnings or errors, it seemed fine. But maybe I not looking for the right thing. For the event switching in lights with the command BEGIN:Billy_r4F_AZ:ON
END:Billy_r4F_AZ:OFF
from 9:50 to 9:53.
I have the following infomation from the logs, but I do not know why I do not get the “sending command ‘ON’ to item” that I received once. Maybe someboby else sees something obvious?
2018-01-05 09:49:13.704 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-start-3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj(BillyRegal@05.01.2018/09:50-05.01.2018/09:53)-0 - [groupName] : event-start - Fri Jan 05 09:50:00 CET 2018
2018-01-05 09:50:00.009 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event BEGIN for: 3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj(BillyRegal@05.01.2018/09:50-05.01.2018/09:53)
2018-01-05 09:50:13.266 [DEBUG] [caldav.internal.job.EventReloaderJob] - running EventReloaderJob for config : UteCal
2018-01-05 09:50:13.269 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading events for config: UteCal
2018-01-05 09:50:13.279 [DEBUG] [caldav.internal.job.EventReloaderJob] - old eventcontainer – id : 3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj – filename : 3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj – calcuntil : 2018-01-06T09:44:13.968+01:00 – lastchanged : 2018-01-05T09:44:05.000+01:00 – ishistoric : false
2018-01-05 09:50:13.284 [DEBUG] [caldav.internal.job.EventReloaderJob] - old eventlist contains the event : BillyRegal – deb : 2018-01-05T09:50:00.000+01:00 – fin : 2018-01-05T09:53:00.000+01:00 – lastchanged 2018-01-05T09:44:05.000+01:00
2018-01-05 09:50:13.683 [DEBUG] [caldav.internal.job.EventReloaderJob] - jobs scheduled :
2018-01-05 09:50:13.687 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj(BillyRegal@05.01.2018/09:50-05.01.2018/09:53)-0 - [groupName] : event-end - Fri Jan 05 09:53:00 CET 2018
2018-01-05 09:52:13.677 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : event-end-3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj(BillyRegal@05.01.2018/09:50-05.01.2018/09:53)-0 - [groupName] : event-end - Fri Jan 05 09:53:00 CET 2018
2018-01-05 09:52:13.683 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : PBCal - [groupName] : event-reloader - Fri Jan 05 09:53:23 CET 2018
2018-01-05 09:52:13.686 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : UteCal - [groupName] : event-reloader - Fri Jan 05 09:53:13 CET 2018
2018-01-05 09:52:13.689 [DEBUG] [caldav.internal.job.EventReloaderJob] - [job] : Commit_Transaction - [groupName] : MapDB_SchedulerGroup - Fri Jan 05 09:52:16 CET 2018
2018-01-05 09:53:00.004 [INFO ] [nhab.io.caldav.internal.job.EventJob] - event END for: 3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj(BillyRegal@05.01.2018/09:50-05.01.2018/09:53)
2018-01-05 09:53:13.267 [DEBUG] [caldav.internal.job.EventReloaderJob] - running EventReloaderJob for config : UteCal
2018-01-05 09:53:13.277 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading events for config: UteCal
2018-01-05 09:53:13.681 [DEBUG] [caldav.internal.job.EventReloaderJob] - loading resource: /calendars/u.weckmann/default/3d7be61a574f5a88cbc93582bdf51e3e-qf9Qxnj.ics (FSchangedTS not valid)
2018-01-05 09:53:13.767 [DEBUG] [caldav.internal.job.EventReloaderJob] - Processing event 'BillyRegal’
2018-01-05 09:53:13.775 [DEBUG] [caldav.internal.job.EventReloaderJob] - Processing periods…
