One KNX command causes two busevents #2508
Description
When I send a command over KNX to OpenHAB, OpenHAB behaves as expected:
13:01:22.319 [DEBUG] [.b.knx.internal.bus.KNXBinding:164 ] - Received groupWrite Event.
13:01:22.319 [INFO ] [tuwien.auto.calimero :51 ] - [KNXnet/IP receiver] link 224.0.23.12:3671: indication from 15.15.1
13:01:22.322 [INFO ] [runtime.busevents :22 ] - Garage_Door_Run received command OFF
13:01:22.322 [DEBUG] [m.r.internal.engine.RuleEngine:298 ] - Executing rule 'Garage_Door_Run received command'
13:01:22.339 [INFO ] [o.model.script.Garage_Door_Run:53 ] - received command: OFF count:1
I get one "runtime.busevents" in OpenHAB and therefore my Rule 'Garage_Door_Run received command' triggers once as expected. Does not matter if I send same Value OFF -> OFF or OFF -> ON
But when I send a command over OpenHAB to KNX, OpenHAB runtime triggers two busevents:
curl --header "Content-Type: text/plain" --request POST --data "OFF" http://192.168.0.100:8080/rest/items/Garage_Door_Run
13:01:44.156 [DEBUG] [o.i.r.i.resources.ItemResource:193 ] - Received HTTP POST request at 'items/Garage_Door_Run' with value 'OFF'.
13:01:44.156 [INFO ] [runtime.busevents :22 ] - Garage_Door_Run received command OFF
13:01:44.159 [INFO ] [tuwien.auto.calimero :51 ] - [EventAdmin Async Event Dispatcher Thread] link 224.0.23.12:3671: send message to 4/2/2, wait for confirmation
13:01:44.159 [DEBUG] [.b.knx.internal.bus.KNXBinding:164 ] - Received groupWrite Event.
13:01:44.159 [DEBUG] [.b.knx.internal.bus.KNXBinding:139 ] - Wrote value 'OFF' to datapoint 'command DP 4/2/2 Garage_Door_Run, DPT main 0 id 1.001, low priority'
13:01:44.159 [INFO ] [tuwien.auto.calimero :51 ] - [KNXnet/IP receiver] link 224.0.23.12:3671: indication from 0.0.0
13:01:44.160 [DEBUG] [m.r.internal.engine.RuleEngine:298 ] - Executing rule 'Garage_Door_Run received command'
13:01:44.160 [INFO ] [runtime.busevents :22 ] - Garage_Door_Run received command OFF
13:01:44.160 [INFO ] [o.model.script.Garage_Door_Run:53 ] - received command: OFF count:1
13:01:44.164 [DEBUG] [m.r.internal.engine.RuleEngine:298 ] - Executing rule 'Garage_Door_Run received command'
13:01:44.164 [INFO ] [o.model.script.Garage_Door_Run:53 ] - received command: OFF count:2
Now I get "runtime.busevents" (13:01:44.159 and 13:01:44.160) twice and therefore my Rule 'Garage_Door_Run received command' triggers twice too and for example mqtt receives two commands.
Same as above, but with KNX Binding TRACE is enabled:
sent from KNX:
2015-04-25 14:15:39.760 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Received groupWrite Event.
2015-04-25 14:15:39.764 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2015-04-25 14:15:39.768 [TRACE] [.b.knx.internal.bus.KNXBinding] - Added event (item='Garage_Door_Run', type='OFF') to the ignore event list
2015-04-25 14:15:39.772 [TRACE] [.b.knx.internal.bus.KNXBinding] - Processed event (item='Garage_Door_Run', type='OFF', destination='4/2/2')
2015-04-25 14:15:39.772 [TRACE] [.b.knx.internal.bus.KNXBinding] - Received command (item='Garage_Door_Run', command='OFF')
2015-04-25 14:15:39.776 [INFO ] [o.model.script.Garage_Door_Run] - received command: OFF count:1
2015-04-25 14:15:39.780 [TRACE] [.b.knx.internal.bus.KNXBinding] - We received this event (item='Garage_Door_Run', state='OFF') from KNX, so we don't send it back again -> ignore!
2015-04-25 14:15:39.795 [INFO ] [runtime.busevents ] - Garage_Door_Run received command OFF
2015-04-25 14:15:42.288 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Received groupWrite Event.
2015-04-25 14:15:42.292 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Received telegram for unknown group address 1/4/0
sent by curl or via mqtt:
2015-04-25 14:10:57.520 [TRACE] [.b.knx.internal.bus.KNXBinding] - Received command (item='Garage_Door_Run', command='OFF')
2015-04-25 14:10:57.520 [INFO ] [o.model.script.Garage_Door_Run] - received command: OFF count:1
2015-04-25 14:10:57.525 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper] - toTypeClass looking for dptId = 1.001
2015-04-25 14:10:57.528 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Wrote value 'OFF' to datapoint 'command DP 4/2/2 Garage_Door_Run, DPT main 0 id 1.001, low priority'
2015-04-25 14:10:57.528 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Received groupWrite Event.
2015-04-25 14:10:57.532 [INFO ] [runtime.busevents ] - Garage_Door_Run received command OFF
2015-04-25 14:10:57.536 [TRACE] [.o.b.k.i.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2015-04-25 14:10:57.540 [TRACE] [.b.knx.internal.bus.KNXBinding] - Added event (item='Garage_Door_Run', type='OFF') to the ignore event list
2015-04-25 14:10:57.548 [TRACE] [.b.knx.internal.bus.KNXBinding] - Processed event (item='Garage_Door_Run', type='OFF', destination='4/2/2')
2015-04-25 14:10:57.551 [TRACE] [.b.knx.internal.bus.KNXBinding] - Received command (item='Garage_Door_Run', command='OFF')
2015-04-25 14:10:57.555 [TRACE] [.b.knx.internal.bus.KNXBinding] - We received this event (item='Garage_Door_Run', state='OFF') from KNX, so we don't send it back again -> ignore!
2015-04-25 14:10:57.555 [INFO ] [o.model.script.Garage_Door_Run] - received command: OFF count:2
2015-04-25 14:10:57.555 [INFO ] [runtime.busevents ] - Garage_Door_Run received command OFF
2015-04-25 14:11:00.876 [DEBUG] [.b.knx.internal.bus.KNXBinding] - Received groupWrite Event.
When I send a state over OpenHAB to KNX, OpenHAB runtime triggers two busevents:
curl --header "Content-Type: text/plain" --request PUT --data "OFF" http://192.168.0.100:8080/rest/items/Garage_Door_Run/state
2015-04-25 17:01:08.769 [INFO ] [runtime.busevents ] - Garage_Door_Run state updated to OFF
2015-04-25 17:01:08.773 [INFO ] [runtime.busevents ] - Garage_Door_Run received command OFF
The originally sent 'state updated' and afterwards a 'received command'.
Without KNX Binding or Items not bound to knx, always only one 'runtime.busevents' is triggered, 'state updated' OR 'received command'.
Normally I would expect to get a command and then afterwards the appropriate state change,
but nor reversed or two commands in a row.
For all knx items, It seams, KNX-Binding always sends additional a 'received command' to the OpenHAB Eventbus.
It is nearly impossible to workaround this effect, and to intercept all cases caused by the second command Event.
Its tested in Version OH 1.7.0 Master but got exactly same behavior in Release 1.6.2.
I can't find the mechanism in source, where this Effect is caused.
Please Help!
Thanks in advance,
Helmut