search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.85k stars 3.56k forks source link

[elerotransmitterstick] binding blocks events from astro binding #8713

Open TheFire666 opened 3 years ago

TheFire666 commented 3 years ago

I'm using elerotransmitterstick binding version 2.5.8 and astro binding version 2.5.8 with openhab 2.5.8-1 on openhabian.

When I have both bindings installed and configured, the events of the astro channels are not triggert at the correct time. The are all triggert at ~00:00:30, just after midnight. When I uninstall the elerotransmitterstick binding, the events are triggerd at the correct time (e.g. sunset). I did some research on the topic and I think that it is a similar problem as reported in https://github.com/openhab/openhab-addons/issues/6584.

2020-10-10 00:00:30.974 [vent.ItemStateChangedEvent] - SunRiseTime changed from 2020-10-09T07:32:00.000+0200 to 2020-10-10T07:33:00.000+0200 2020-10-10 00:00:30.990 [vent.ItemStateChangedEvent] - Sunrise_Time changed from 2020-10-09T07:32:00.000+0200 to 2020-10-10T07:33:00.000+0200 2020-10-10 00:00:31.000 [vent.ItemStateChangedEvent] - Sunset_Time changed from 2020-10-09T18:40:00.000+0200 to 2020-10-10T18:38:00.000+0200 2020-10-10 00:00:31.013 [vent.ItemStateChangedEvent] - SunSetTime changed from 2020-10-09T18:40:00.000+0200 to 2020-10-10T18:38:00.000+0200 2020-10-10 00:00:31.027 [vent.ItemStateChangedEvent] - CivDawn_Time changed from 2020-10-09T07:32:00.000+0200 to 2020-10-10T07:33:00.000+0200 2020-10-10 00:00:31.034 [vent.ChannelTriggeredEvent] - astro:sun:home:morningNight#event triggered END 2020-10-10 00:00:31.042 [vent.ItemStateChangedEvent] - CivDusk_Time changed from 2020-10-09T18:43:00.000+0200 to 2020-10-10T18:41:00.000+0200 2020-10-10 00:00:31.048 [vent.ChannelTriggeredEvent] - astro:sun:home:astroDawn#event triggered START 2020-10-10 00:00:31.056 [vent.ChannelTriggeredEvent] - astro:sun:home:astroDawn#event triggered END 2020-10-10 00:00:31.062 [vent.ChannelTriggeredEvent] - astro:sun:home:nauticDawn#event triggered START 2020-10-10 00:00:31.069 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered START 2020-10-10 00:00:31.076 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered END 2020-10-10 00:00:31.081 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDawn#event triggered END 2020-10-10 00:00:31.089 [vent.ChannelTriggeredEvent] - astro:sun:home:nauticDawn#event triggered END 2020-10-10 00:00:31.095 [vent.ChannelTriggeredEvent] - astro:sun:home:noon#event triggered START 2020-10-10 00:00:31.102 [vent.ChannelTriggeredEvent] - astro:sun:home:set#event triggered START 2020-10-10 00:00:31.108 [vent.ChannelTriggeredEvent] - astro:sun:home:daylight#event triggered START 2020-10-10 00:00:31.114 [vent.ChannelTriggeredEvent] - astro:sun:home:rise#event triggered START 2020-10-10 00:00:31.118 [vent.ChannelTriggeredEvent] - astro:sun:home:daylight#event triggered END 2020-10-10 00:00:31.123 [vent.ChannelTriggeredEvent] - astro:sun:home:noon#event triggered END 2020-10-10 00:00:31.128 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDusk#event triggered END ==> /var/log/openhab2/openhab.log <== 2020-10-10 00:00:31.129 [INFO ] [se.smarthome.model.script.SunsetLog1] - Astro binding set event ==> /var/log/openhab2/events.log <== 2020-10-10 00:00:31.134 [vent.ChannelTriggeredEvent] - astro:sun:home:set#event triggered END 2020-10-10 00:00:31.140 [vent.ChannelTriggeredEvent] - astro:sun:home:civilDusk#event triggered START 2020-10-10 00:00:31.145 [vent.ChannelTriggeredEvent] - astro:sun:home:nauticDusk#event triggered END 2020-10-10 00:00:31.149 [vent.ChannelTriggeredEvent] - astro:sun:home:night#event triggered START 2020-10-10 00:00:31.154 [vent.ChannelTriggeredEvent] - astro:sun:home:astroDusk#event triggered END 2020-10-10 00:00:31.159 [vent.ChannelTriggeredEvent] - astro:sun:home:astroDusk#event triggered START ==> /var/log/openhab2/openhab.log <== 2020-10-10 00:00:31.158 [INFO ] [se.smarthome.model.script.SunsetLog1] - Astro binding set event ==> /var/log/openhab2/events.log <== 2020-10-10 00:00:31.164 [vent.ChannelTriggeredEvent] - astro:sun:home:nauticDusk#event triggered START 2020-10-10 00:00:31.170 [vent.ChannelTriggeredEvent] - astro:sun:home:morningNight#event triggered START 2020-10-10 00:00:31.174 [vent.ChannelTriggeredEvent] - astro:sun:home:eveningNight#event triggered START

TheFire666 commented 3 years ago

I changed the log level of the elerotransmitterstick binding to trace, but I don't quite understand it. There are delayed commands set with 5000000ms=5000s~83min which seems quite long. Maybe the delay blocks the events of the astro binding?

08:06:35.900 [INFO ] [smarthome.event.ItemStateChangedEvent] - ElternTuer changed from 100 to 0 08:08:11.381 [INFO ] [smarthome.event.ItemStateChangedEvent] - Sophie changed from 100 to 0 08:20:33.959 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerLinks changed from 100 to 0 08:20:34.140 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerMitte changed from 100 to 0 08:20:34.501 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerRechts changed from 100 to 0 08:20:34.676 [INFO ] [smarthome.event.ItemStateChangedEvent] - Kueche changed from 100 to 0 08:20:34.900 [INFO ] [smarthome.event.ItemStateChangedEvent] - Esszimmer changed from 100 to 0 09:00:00.023 [INFO ] [clipse.smarthome.model.script.cronLog] - Cron job executed 09:00:00.069 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'WohnzimmerLinks' received command UP 09:00:00.111 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'WohnzimmerMitte' received command UP 09:00:00.113 [DEBUG] [.internal.handler.EleroChannelHandler] - Received command UP for channel elerotransmitterstick:elerochannel:a0196121:1:control 09:00:00.130 [DEBUG] [stick.internal.stick.TransmitterStick] - adding command UP for channel ids [1] to queue... 09:00:00.131 [INFO ] [arthome.event.ItemStatePredictedEvent] - WohnzimmerLinks predicted to become UP 09:00:00.135 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command UP on channels [1] with priority 20 09:00:00.139 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:00.142 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 10 09:00:00.146 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command UP on channels [1] with priority 20 09:00:00.154 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA054C000120E4 09:00:00.158 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:00.163 [DEBUG] [.internal.handler.EleroChannelHandler] - Received command UP for channel elerotransmitterstick:elerochannel:a0196121:2:control 09:00:00.167 [DEBUG] [stick.internal.stick.TransmitterStick] - adding command UP for channel ids [2] to queue... 09:00:00.182 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'WohnzimmerRechts' received command UP 09:00:00.217 [DEBUG] [.internal.handler.EleroChannelHandler] - Received command UP for channel elerotransmitterstick:elerochannel:a0196121:3:control 09:00:00.221 [DEBUG] [stick.internal.stick.TransmitterStick] - adding command UP for channel ids [3] to queue... 09:00:00.242 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'Kueche' received command UP 09:00:00.267 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:00.273 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:00.275 [DEBUG] [.internal.handler.EleroChannelHandler] - Received command UP for channel elerotransmitterstick:elerochannel:a0196121:4:control 09:00:00.278 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 1, 10, -7] 09:00:00.278 [DEBUG] [stick.internal.stick.TransmitterStick] - adding command UP for channel ids [4] to queue... 09:00:00.283 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:00.287 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:00.292 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:00.295 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:00.296 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered MOVING_UP for channels [1] for packet AA054C000120E4. 09:00:00.297 [INFO ] [smarthome.event.ItemCommandEvent ] - Item 'Esszimmer' received command UP 09:00:00.299 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state MOVING_UP for thing elerotransmitterstick:elerochannel:a0196121:1 09:00:00.300 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:00.304 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:00.306 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids 1 to queue with delay 2000... 09:00:00.307 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 10 from buffer 09:00:00.309 [INFO ] [arthome.event.ItemStatePredictedEvent] - WohnzimmerMitte predicted to become UP 09:00:00.318 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -7 from buffer 09:00:00.309 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:00.326 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:00.326 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:00:00.329 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command UP on channels [2] with priority 20 09:00:00.332 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:00.336 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 2 commands, active queue size is 3, queue size is 10 09:00:00.336 [DEBUG] [.internal.handler.EleroChannelHandler] - Received command UP for channel elerotransmitterstick:elerochannel:a0196121:5:control 09:00:00.339 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command UP on channels [2] with priority 20 09:00:00.344 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA054C000220E3 09:00:00.345 [DEBUG] [stick.internal.stick.TransmitterStick] - adding command UP for channel ids [5] to queue... 09:00:00.348 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:00.357 [INFO ] [arthome.event.ItemStatePredictedEvent] - WohnzimmerRechts predicted to become UP 09:00:00.376 [INFO ] [arthome.event.ItemStatePredictedEvent] - Kueche predicted to become UP 09:00:00.395 [INFO ] [arthome.event.ItemStatePredictedEvent] - Esszimmer predicted to become UP 09:00:00.436 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerLinks changed from 0 to 50 09:00:00.506 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:00.510 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:00.513 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 2, 10, -8] 09:00:00.516 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:00.518 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:00.521 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:00.521 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered MOVING_UP for channels [2] for packet AA054C000220E3. 09:00:00.524 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:00.524 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state MOVING_UP for thing elerotransmitterstick:elerochannel:a0196121:2 09:00:00.527 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:00.530 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 2 from buffer 09:00:00.532 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 10 from buffer 09:00:00.534 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids 2 to queue with delay 2000... 09:00:00.535 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -8 from buffer 09:00:00.537 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:00.538 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:00.539 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerMitte changed from 0 to 50 09:00:00.544 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:00.547 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 1 commands, active queue size is 3, queue size is 10 09:00:00.551 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command UP on channels [3] with priority 20 09:00:00.554 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA054C000420E1 09:00:00.557 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:00.650 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:00.653 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:00.655 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 4, 10, -10] 09:00:00.658 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:00.660 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:00.662 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:00.662 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered MOVING_UP for channels [3] for packet AA054C000420E1. 09:00:00.665 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:00.665 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state MOVING_UP for thing elerotransmitterstick:elerochannel:a0196121:3 09:00:00.668 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:00.671 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 4 from buffer 09:00:00.672 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids 3 to queue with delay 2000... 09:00:00.673 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 10 from buffer 09:00:00.675 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:00.676 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -10 from buffer 09:00:00.678 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:00.679 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:00.681 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 2, queue size is 10 09:00:00.682 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerRechts changed from 0 to 50 09:00:00.684 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command UP on channels [4] with priority 20 09:00:00.687 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA054C000820DD 09:00:00.691 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:00.794 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:00.797 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:00.799 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 8, 10, -14] 09:00:00.801 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:00.804 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:00.806 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:00.806 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered MOVING_UP for channels [4] for packet AA054C000820DD. 09:00:00.809 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:00.809 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state MOVING_UP for thing elerotransmitterstick:elerochannel:a0196121:4 09:00:00.811 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:00.814 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 8 from buffer 09:00:00.815 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids 4 to queue with delay 2000... 09:00:00.819 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 10 from buffer 09:00:00.819 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:00.821 [INFO ] [smarthome.event.ItemStateChangedEvent] - Kueche changed from 0 to 50 09:00:00.822 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:00.824 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -14 from buffer 09:00:00.827 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:00.827 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 10 09:00:00.830 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command UP on channels [5] with priority 20 09:00:00.833 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA054C001020D5 09:00:00.836 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:00.922 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:00.925 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:00.928 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 16, 10, -22] 09:00:00.930 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:00.932 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:00.935 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:00.935 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered MOVING_UP for channels [5] for packet AA054C001020D5. 09:00:00.937 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:00.938 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state MOVING_UP for thing elerotransmitterstick:elerochannel:a0196121:5 09:00:00.940 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:00.943 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 16 from buffer 09:00:00.944 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids 5 to queue with delay 2000... 09:00:00.947 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:00.948 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 10 from buffer 09:00:00.949 [INFO ] [smarthome.event.ItemStateChangedEvent] - Esszimmer changed from 0 to 50 09:00:00.950 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:00:00.952 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -22 from buffer 09:00:00.955 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:02.309 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [1] with priority 10 and delay -1 09:00:02.312 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:02.314 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:00:02.317 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [1] with priority 10 and delay -9 09:00:02.320 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000103 09:00:02.323 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:02.455 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:02.458 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 3 bytes. 09:00:02.460 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 3 bytes: [-86, 5, 77] 09:00:02.463 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:02.486 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:02.489 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:02.492 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 1, 1, 2] 09:00:02.494 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:02.496 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:02.499 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [1] for packet AA044E000103. 09:00:02.499 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:02.501 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:02.501 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:1 09:00:02.504 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:02.506 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:02.508 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [1] to queue with delay 5000000... 09:00:02.508 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:02.511 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 2 from buffer 09:00:02.511 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:02.513 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:02.513 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:00:02.519 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerLinks changed from 50 to 0 09:00:02.537 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [2] with priority 10 and delay 0 09:00:02.540 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:02.542 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:00:02.545 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [2] with priority 10 and delay -7 09:00:02.547 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000202 09:00:02.550 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:02.727 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:02.731 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:02.733 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 2, 1, 1] 09:00:02.736 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:02.739 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:02.742 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:02.742 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [2] for packet AA044E000202. 09:00:02.744 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:02.745 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:2 09:00:02.747 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:02.750 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 2 from buffer 09:00:02.753 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:02.754 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [2] to queue with delay 5000000... 09:00:02.755 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:02.757 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:02.757 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:02.758 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerMitte changed from 50 to 0 09:00:02.762 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:00:02.765 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [3] with priority 10 and delay -89 09:00:02.768 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:02.771 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:00:02.775 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [3] with priority 10 and delay -99 09:00:02.777 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000400 09:00:02.781 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:02.903 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:02.906 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:02.909 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 4, 1, -1] 09:00:02.913 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:02.916 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:02.919 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:02.919 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [3] for packet AA044E000400. 09:00:02.921 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:02.921 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:3 09:00:02.924 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:02.926 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 4 from buffer 09:00:02.929 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:02.930 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [3] to queue with delay 5000000... 09:00:02.932 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -1 from buffer 09:00:02.933 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:02.934 [INFO ] [smarthome.event.ItemStateChangedEvent] - WohnzimmerRechts changed from 50 to 0 09:00:02.935 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:02.937 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:00:02.941 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [4] with priority 10 and delay -121 09:00:02.943 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:02.947 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 1 commands, active queue size is 2, queue size is 8 09:00:02.950 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [4] with priority 10 and delay -130 09:00:02.954 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E0008FC 09:00:02.957 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:03.031 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:03.035 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:03.037 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 8, 1, -5] 09:00:03.040 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:03.042 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:03.045 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:03.045 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [4] for packet AA044E0008FC. 09:00:03.047 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:03.048 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:4 09:00:03.050 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:03.052 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 8 from buffer 09:00:03.055 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:03.056 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [4] to queue with delay 5000000... 09:00:03.058 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -5 from buffer 09:00:03.059 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:03.061 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:03.061 [INFO ] [smarthome.event.ItemStateChangedEvent] - Kueche changed from 50 to 0 09:00:03.062 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:00:03.066 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:00:03.069 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [5] with priority 10 and delay -122 09:00:03.073 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E0010F4 09:00:03.075 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:00:03.190 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:00:03.193 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:00:03.195 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 16, 1, -13] 09:00:03.198 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:00:03.200 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:00:03.203 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:00:03.203 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [5] for packet AA044E0010F4. 09:00:03.205 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:00:03.206 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:5 09:00:03.210 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:00:03.213 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 16 from buffer 09:00:03.217 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:00:03.221 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -13 from buffer 09:00:03.222 [INFO ] [smarthome.event.ItemStateChangedEvent] - Esszimmer changed from 50 to 0 09:00:03.225 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:00:03.230 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [5] to queue with delay 5000000... 09:00:03.232 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:00:03.235 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:29:55.770 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [12] with priority 0 and delay -1 09:29:55.828 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:29:55.833 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:29:55.837 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [12] with priority 0 and delay -68 09:29:55.842 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E0800FC 09:29:55.852 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:29:55.957 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:29:55.965 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:29:55.971 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 8, 0, 1, -5] 09:29:55.976 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:29:55.982 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:29:55.988 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [12] for packet AA044E0800FC. 09:29:55.988 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:29:55.997 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:29:56.003 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 8 from buffer 09:29:56.006 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:12 09:29:56.008 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:29:56.016 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:29:56.019 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [12] to queue with delay 5000000... 09:29:56.022 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -5 from buffer 09:29:56.027 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:29:56.032 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:29:56.036 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:29:56.043 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [11] with priority 0 and delay -146 09:29:56.049 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:29:56.055 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:29:56.061 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [11] with priority 0 and delay -164 09:29:56.068 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E040000 09:29:56.074 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:29:56.260 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:29:56.267 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:29:56.273 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 4, 0, 1, -1] 09:29:56.279 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:29:56.285 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:29:56.292 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:29:56.292 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [11] for packet AA044E040000. 09:29:56.298 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:29:56.301 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:11 09:29:56.305 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 4 from buffer 09:29:56.313 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:29:56.313 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [11] to queue with delay 5000000... 09:29:56.320 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:29:56.323 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:29:56.328 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -1 from buffer 09:29:56.330 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:29:56.335 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:31:28.374 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [14] with priority 0 and delay 0 09:31:28.384 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:31:28.394 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:31:28.402 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [14] with priority 0 and delay -28 09:31:28.411 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E2000E4 09:31:28.420 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:31:29.220 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:31:29.231 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:31:29.241 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 32, 0, 1, -29] 09:31:29.250 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:31:29.259 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:31:29.268 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [14] for packet AA044E2000E4. 09:31:29.268 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:31:29.279 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:14 09:31:29.283 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:31:29.299 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 32 from buffer 09:31:29.302 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [14] to queue with delay 5000000... 09:31:29.310 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:31:29.320 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:31:29.325 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:31:29.333 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:31:29.338 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -29 from buffer 09:31:29.348 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [13] with priority 0 and delay -780 09:31:29.353 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:31:29.362 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:31:29.373 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:31:29.382 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [13] with priority 0 and delay -814 09:31:29.390 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E1000F4 09:31:29.397 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:31:29.492 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:31:29.500 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 3 bytes. 09:31:29.507 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 3 bytes: [-86, 5, 77] 09:31:29.515 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:31:29.545 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:31:29.552 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:31:29.560 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 16, 0, 1, -13] 09:31:29.568 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:31:29.576 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:31:29.584 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [13] for packet AA044E1000F4. 09:31:29.585 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:31:29.595 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:13 09:31:29.601 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:31:29.616 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 16 from buffer 09:31:29.616 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [13] to queue with delay 5000000... 09:31:29.625 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:31:29.634 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:31:29.640 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:31:29.649 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:31:29.656 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -13 from buffer 09:31:29.672 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 09:31:31.378 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [15] with priority 0 and delay -1 09:31:31.386 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 09:31:31.396 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 09:31:31.404 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [15] with priority 0 and delay -27 09:31:31.413 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E4000C4 09:31:31.422 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 09:31:31.568 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 09:31:31.578 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 09:31:31.588 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 64, 0, 1, -61] 09:31:31.597 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 09:31:31.606 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 09:31:31.615 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 09:31:31.615 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [15] for packet AA044E4000C4. 09:31:31.625 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 09:31:31.632 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:15 09:31:31.637 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 64 from buffer 09:31:31.651 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [15] to queue with delay 5000000... 09:31:31.654 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 09:31:31.663 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 09:31:31.668 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 09:31:31.678 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 09:31:31.683 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -61 from buffer 09:31:31.698 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 10:23:22.511 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [1] with priority 0 and delay 0 10:23:22.518 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 10:23:22.525 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 10:23:22.532 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [1] with priority 0 and delay -22 10:23:22.539 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000103 10:23:22.546 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 10:23:22.623 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:22.637 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 10:23:22.643 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 1, 1, 2] 10:23:22.650 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:22.656 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 10:23:22.662 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 10:23:22.662 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [1] for packet AA044E000103. 10:23:22.667 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 10:23:22.673 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:1 10:23:22.675 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 10:23:22.683 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:22.690 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:22.690 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [1] to queue with delay 5000000... 10:23:22.696 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 2 from buffer 10:23:22.701 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 10:23:22.704 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 10:23:22.709 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 10:23:22.758 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [2] with priority 0 and delay 0 10:23:22.764 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 10:23:22.771 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 10:23:22.777 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [2] with priority 0 and delay -20 10:23:22.784 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000202 10:23:22.791 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 10:23:22.894 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:22.900 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 10:23:22.906 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 2, 1, 1] 10:23:22.911 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:22.917 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 10:23:22.923 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 10:23:22.923 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [2] for packet AA044E000202. 10:23:22.929 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 10:23:22.934 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:2 10:23:22.937 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 10:23:22.945 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 2 from buffer 10:23:22.950 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [2] to queue with delay 5000000... 10:23:22.952 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:22.958 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 10:23:22.961 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:22.966 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 10:23:22.969 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 10:23:22.974 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [3] with priority 0 and delay -41 10:23:22.982 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 10:23:22.988 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 10:23:22.995 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [3] with priority 0 and delay -62 10:23:23.002 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E000400 10:23:23.009 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 10:23:23.197 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:23.204 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 10:23:23.210 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 4, 1, -1] 10:23:23.217 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:23.223 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 10:23:23.229 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 10:23:23.229 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [3] for packet AA044E000400. 10:23:23.235 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 10:23:23.241 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:3 10:23:23.245 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 10:23:23.252 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 4 from buffer 10:23:23.258 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [3] to queue with delay 5000000... 10:23:23.258 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:23.265 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 10:23:23.267 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -1 from buffer 10:23:23.272 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 10:23:23.275 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 10:23:23.281 [TRACE] [stick.internal.stick.TransmitterStick] - take returned Command INFO on channels [4] with priority 0 and delay -222 10:23:23.288 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 10:23:23.294 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 1 commands, active queue size is 2, queue size is 8 10:23:23.300 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [4] with priority 0 and delay -242 10:23:23.307 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E0008FC 10:23:23.314 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 10:23:23.405 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:23.411 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 3 bytes. 10:23:23.416 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 3 bytes: [-86, 5, 77] 10:23:23.422 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:23.448 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:23.454 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 10:23:23.460 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 8, 1, -5] 10:23:23.465 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:23.471 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 10:23:23.476 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 10:23:23.476 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [4] for packet AA044E0008FC. 10:23:23.482 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 10:23:23.487 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:4 10:23:23.489 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 10:23:23.497 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 8 from buffer 10:23:23.502 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [4] to queue with delay 5000000... 10:23:23.503 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:23.510 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 10:23:23.513 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -5 from buffer 10:23:23.519 [TRACE] [stick.internal.stick.TransmitterStick] - Draining all available commands... 10:23:23.522 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: [] 10:23:23.527 [TRACE] [stick.internal.stick.TransmitterStick] - Drained 0 commands, active queue size is 1, queue size is 9 10:23:23.535 [DEBUG] [stick.internal.stick.TransmitterStick] - active command is Command INFO on channels [5] with priority 0 and delay -303 10:23:23.542 [DEBUG] [stick.internal.stick.SerialConnection] - Writing packet to stick: AA044E0010F4 10:23:23.548 [TRACE] [stick.internal.stick.SerialConnection] - Waiting 4000 ms for answer from stick... 10:23:23.677 [TRACE] [stick.internal.stick.SerialConnection] - parsing input... 10:23:23.683 [TRACE] [stick.internal.stick.SerialConnection] - input parsed. buffer contains 7 bytes. 10:23:23.688 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 7 bytes: [-86, 5, 77, 0, 16, 1, -13] 10:23:23.694 [TRACE] [stick.internal.stick.SerialConnection] - packet length is 5 bytes. 10:23:23.699 [TRACE] [stick.internal.stick.SerialConnection] - response type is EASY_ACK. 10:23:23.704 [DEBUG] [stick.internal.stick.SerialConnection] - Stick answered TOP for channels [5] for packet AA044E0010F4. 10:23:23.704 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 5 from buffer 10:23:23.711 [DEBUG] [.internal.handler.EleroChannelHandler] - Received updated state TOP for thing elerotransmitterstick:elerochannel:a0196121:5 10:23:23.713 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 77 from buffer 10:23:23.720 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 0 from buffer 10:23:23.726 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 16 from buffer 10:23:23.726 [DEBUG] [stick.internal.stick.TransmitterStick] - adding timed command INFO for channel ids [5] to queue with delay 5000000... 10:23:23.732 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte 1 from buffer 10:23:23.737 [TRACE] [stick.internal.stick.TransmitterStick] - finished waiting. connection open=true, terminated=false 10:23:23.739 [TRACE] [stick.internal.stick.SerialConnection] - dropping byte -13 from buffer 10:23:23.744 [DEBUG] [stick.internal.stick.TransmitterStick] - No due commands, invoking take on queue... 10:23:23.747 [TRACE] [stick.internal.stick.SerialConnection] - buffer contains 0 bytes: []

lsiepel commented 1 year ago

Around the time this issue was logged there were several related PR's in core and addons repo to fix this and similar issues. Could you verify if this is still an issue with 3.4.0?

sisko84 commented 1 year ago

Hi. I am on 3.4.1 (Astro and Elero Binding) and this is still an issue.

lsiepel commented 1 year ago

The Astro binding has a fixed job running at 00:30 every night. And a set of jobs that are schedueld at the event. According to this issue, it seems like the scheduling of those events are mallfuncitoning due to the elero binding interfering. I cannot reproduce this issue yet and i can;t see a clear error in the code yet. So it would be helpfull if both bindings can be put in debug mode and output the logging to seperate files. If you could provide those, it would be of a great help to get this fixed.

sisko84 commented 1 year ago

Hi Isiepel, I added the configuration to log astro and elerotransmitterstick in separate files (DEBUG) and can provide them after a few days. But I do not know if they still help. As I had a closer look in the logfiles today, I recognized that the behavior of the astro events seems to be normal right now. Interesting: I added a new thing (shelly) and directly after that a few astro events were fired and from that time on (2023-01-20 14:13:47.), no more unusual events occur at midnight:

` 2023-01-19 00:00:31.128 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered END 2023-01-19 00:00:31.132 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered START 2023-01-19 00:00:31.136 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered END 2023-01-19 00:00:31.139 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered START 2023-01-19 00:00:31.142 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered END 2023-01-19 00:00:31.145 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered START 2023-01-19 00:00:31.147 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END 2023-01-19 00:00:31.150 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START 2023-01-19 00:00:31.152 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered END 2023-01-19 00:00:31.155 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered START 2023-01-19 00:00:31.157 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered START 2023-01-19 00:00:31.160 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered END 2023-01-19 00:00:31.162 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered START 2023-01-19 00:00:31.164 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered END 2023-01-19 00:00:31.167 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDusk#event triggered START 2023-01-19 00:00:31.169 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDusk#event triggered START 2023-01-19 00:00:31.171 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDusk#event triggered END 2023-01-19 00:00:31.175 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered END 2023-01-19 00:00:31.178 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDusk#event triggered END 2023-01-19 00:00:31.180 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDusk#event triggered START 2023-01-19 00:00:31.182 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDusk#event triggered END 2023-01-19 00:00:31.184 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:eveningNight#event triggered START 2023-01-19 00:00:31.186 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered START 2023-01-19 00:00:31.189 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:night#event triggered START

2023-01-20 00:00:31.134 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered END 2023-01-20 00:00:31.138 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered START 2023-01-20 00:00:31.141 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered START 2023-01-20 00:00:31.144 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered END 2023-01-20 00:00:31.146 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered END 2023-01-20 00:00:31.148 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END 2023-01-20 00:00:31.151 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START 2023-01-20 00:00:31.153 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered START 2023-01-20 00:00:31.156 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered END 2023-01-20 00:00:31.158 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered START 2023-01-20 00:00:31.160 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered END 2023-01-20 00:00:31.162 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered START 2023-01-20 00:00:31.165 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered END 2023-01-20 00:00:31.167 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered END 2023-01-20 00:00:31.170 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered START 2023-01-20 00:00:31.172 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDusk#event triggered START 2023-01-20 00:00:31.174 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDusk#event triggered START 2023-01-20 00:00:31.176 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDusk#event triggered START 2023-01-20 00:00:31.179 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:eveningNight#event triggered START 2023-01-20 00:00:31.181 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDusk#event triggered END 2023-01-20 00:00:31.183 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDusk#event triggered END 2023-01-20 00:00:31.185 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:night#event triggered START 2023-01-20 00:00:31.187 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDusk#event triggered END 2023-01-20 00:00:31.190 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered START

2023-01-20 13:32:07.901 [INFO ] [openhab.event.InboxAddedEvent ] - Discovery Result with UID 'shelly:shellyplus1pm:4855199a8150' has been added. 2023-01-20 14:13:47.189 [INFO ] [openhab.event.InboxRemovedEvent ] - Discovery Result with UID 'shelly:shellyplus1pm:4855199a8150' has been removed. 2023-01-20 14:13:47.391 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:4855199a8150' changed from UNINITIALIZED to INITIALIZING 2023-01-20 14:13:47.407 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered START 2023-01-20 14:13:47.409 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered END 2023-01-20 14:13:47.411 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered END 2023-01-20 14:13:47.413 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered START 2023-01-20 14:13:47.415 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:nauticDawn#event triggered END 2023-01-20 14:13:47.417 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered START 2023-01-20 14:13:47.419 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDawn#event triggered END 2023-01-20 14:13:47.421 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered START 2023-01-20 14:13:47.422 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:rise#event triggered END 2023-01-20 14:13:47.424 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered START 2023-01-20 14:13:47.426 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered START 2023-01-20 14:13:47.427 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:noon#event triggered END 2023-01-20 14:13:49.417 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:4855199a8150' changed from INITIALIZING to UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafm odus. 2023-01-20 14:13:49.835 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'shelly:shellyplus1pm:4855199a8150' changed from UNKNOWN (CONFIGURATION_PENDING): Initialisierung oder Gerät im Schlafmodus. to ONLINE

2023-01-20 16:56:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered START 2023-01-20 16:56:00.005 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:daylight#event triggered END 2023-01-20 16:56:06.653 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PvGartenhausSpannung' changed from 226.4 V to 227 V 2023-01-20 16:57:06.778 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PvGartenhausSpannung' changed from 227 V to 226.8 V 2023-01-20 16:58:06.868 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PvGartenhausSpannung' changed from 226.8 V to 227 V 2023-01-20 16:59:06.950 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'PvGartenhausSpannung' changed from 227 V to 227.3 V 2023-01-20 17:00:00.002 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:set#event triggered END 2023-01-20 17:00:00.005 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:civilDusk#event triggered START

2023-01-21 00:00:31.153 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered START 2023-01-21 06:21:00.001 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:astroDawn#event triggered START 2023-01-21 06:21:00.003 [INFO ] [openhab.event.ChannelTriggeredEvent ] - astro:sun:local:morningNight#event triggered END `

lsiepel commented 1 year ago

That is very odd, and doesn't look like a coincidence. Will look at the astro and shelly binding. Looks scheduler related; the shelly probably starts a discovery scheduler and that somehow flips the allready scheduled tasks by the astro binding. But have to spend some time on this as it is not that easy to reproduce. Thanks for recording the logs!

lsiepel commented 11 months ago

Late follow up; i did not find anything usefull, sorry. Maybe one of the @openhab/add-ons-maintainers can point in some directions to check?

lsiepel commented 7 months ago

@sisko84 does it still happen with 4.0.x stable?

stale[bot] commented 4 months ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.