One KNX command causes two busevents

[lewie]

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

[lewie]

The following cause is responsible for the second event in openHAB bus:

Internal events coming from 'openHAB event bus' a second time to be sent back to the 'openHAB event bus'.

Case1: Event from direction KNX-bus KNX-bus -> KNX-binding processing -> triggers first 'runtime.busevents'

Case2: Event from direction Openhab OpenHAB-gui -> triggers first 'runtime.busevents' -> KNX-binding processing -> triggers second 'runtime.busevents'

KNX-binding processing (until now) does not differentiate if the origin of an event comes from direction KNX-bus or openHAB event bus. Therefore the binding sends in both cases a command on the 'openHAB event bus'. When the origin of events is the 'openHAB event bus' KNX-bus must not send back in this direction, where it comes from.

For the KNX-binding the KNX source address of openHAB is always 0.0.0. I changed function readFromKNX that it can differentiate if an event comes from Openhab and filter these events.

Side effects and more noticed: I'm a little surprised that this bug has nobody disturbed, therefore and for backward compatibility I made a new optional Configuration Switch:

# Ignore local KNX Events, prevents internal events coming from 'openHAB event bus'
# a second time to be sent back to the 'openHAB event bus'. (optional, defaults to false)
#knx:ignorelocalevents=
knx:ignorelocalevents=true

During the analysis i had to connect my Testsystem to my knx-bus, so that two KNX-binding with KNX source address 0.0.0 compete in same KNX-bus. Therefore i extended one more new optional Configuration Entry:

# Local KNX Binding bus address.(optional, defaults to 0.0.0)
# Use it, when two or more openHAB Instances are connected to the same KNX bus.
#knx:busaddr=
knx:busaddr=15.10.1

Found out, retries in Configuration was never used in Code, so I extended KNXBindingDatapointReaderTask to use knx:readRetries:

# Number of read retries while initialization items from the KNX bus (optional,
# defaults to 3)
#knx:readRetries
knx:readRetries=10

In my KNX Setup (ca. 200 addresses and IP-Router over broadcast) I had sometimes timeouts. Played around and found out:

• knx:timeout: The default 10 Seconds for mine is much too long setting to 1 Second, timeouts go less.
• knx:numberOfThreads: default 5, I have now 50, timeouts disappear.
• knx:readRetries: default 3, I set it to 10

For testing, you can find a patch and jar here: https://groups.google.com/forum/#!category-topic/openhab/discussions/mMY_tEjHg84

The Source can be found here: commit: KNXBinding commit: KNXBindingDatapointReaderTask and KNXConnection Don't understand, why github the hole File shows as changed, in KNXBinding.java I changed some lines...

Hope this helps anybody. Helmut

And how does it proceed now? Testing, Pull request... this is new for me.

[udo1toni]

There was definitly some "strange behavior" around knx, but I could never tell exactly what. For example, in some circumstances, a postUpdate resulted in a sendCommand, (ages ago, so no reliable info) I have another glitch with knx - I own about 20 Rollershutters, when moving them with group.member.forEach(member|member.sendCommand(UP/DOWN)) there are often (not everytime) one or two Rollershutters, which don't move untill I force them manually (from openHAB-UI or knx), so timeout and numberOfThreads hopefully will solve this problem.

[lewie]

KNX binding only sends Commands, never have seen it sends a State changes?! Although it is implemented in the code. But this is more a architecture thing.

The glitch with two 'runtime.busevents' does not directly disturb KNX communiction, but it creates chaos on openHAB event bus. (dual call of rules, toggle does not work and so on)

First for your Rollershutters, make a little pause between commands for KNX: https://github.com/openhab/openhab/wiki/Samples-Tricks#item-loops-with-delay It is not another glitch you have, its exactly mine too: Often not everytime some commands will be lost. I had this effect more strange over gui: click a Switch first and second Time -> OK, Then when I clicked Switch in 500 ms manner, I got dropouts about 1-5 seconds, after that it worked for 1-5 seconds and so on. But all the commands where sent to openHAB Event Bus, therefore it seems calimero or a Coniguration/Syncronisation of calimero does not its job. Could stem the timeouts and dropouts over the Configuration, works since two days... fingers cross!

It would be cool if you can test and feedback my changes: For testing, you can find a patch and jar here: https://groups.google.com/forum/#!category-topic/openhab/discussions/mMY_tEjHg84

[Snickermicker]

Continued from source code comments: As for the read retries: I completely agree. My comment was directed at your proposed solution. The purpose of the ReaderScheduler and the ReaderTask was to have one central queue holding all pending reads from KNX and thus being able to avoid parallel access to the KNX bus and maintain minimum pause times etc. My suggestion was: if a read times out, add the datapoint back to the queue, it will then be read again when its there again. The only thing that needs changing would be that the queue entries are not datapoints but objects holding the datapoint, and number of retries. A datapoint wouldn't be added to the queue again if it's number of retries is exceeding the threshold.

[Snickermicker]

Another thing. I might be completely wrong, but I thought the reason for using commands is that openHAB can/should be able to act as bridge between bindings. Example: toggling of an KNX wall switch could result in an Enocean command, if so configured (and vice versa) If I get it right, then the flow would be: KNX bus -> KNX binding -> openHAB bus -> Enocean binding -> Enocean. I guess, this wouldn't work if the KNX binding would just use postUpdate().

[lewie]

@Snickermicker: Yes, it was a quick test solution, I know. Datapoints now goes back to the readQueue. But did not extend readQueue, I hold only the retries in a plain new Map.

The other Thing: Now I understand why only commands in KNX binding. Also it would be very heavy to transfer the different Bus Architectures (read-write <-> command-state). Command is enough I think.

[lewie]

@Snickermicker: I have tested my KNX changes very well now, its working without side effects or errors (on my systems). Whats next? PullRequest? If yes, how do I do it, I had not created a special branch? It would be my first PullRequest, need a bit help.

[J-N-K]

What I do from your oben master branch:

git checkout -b fix-knx-issue

Copy changed files to that branch

git commit -a
git push -u origin fix-knx-issue

Create a pull request with the web-interface. If your master branch is not up-to-date with openhab/master, update your master branch before creating your feature-branch.

[lewie]

@J-N-K: Thank you for your quick reply.

I think my problem is, that I did not make a Stag0 Brunch after I made my Fork of openhab/master. After that I lively commited other changes to (made no Branch before) and so on, after that I commited my knx-fixes (made no Branch before too). So I think I've created a big mess in my fork.

If I make a new "fix-knx-issue" branch now, with underlying other changes, I'll get no useful PullRequest (only changes from knx-fixes) for openhab/master, isn't it?

Think I have to reset my fork?! Then I could begin to commit more structured with branches and so on.

[J-N-K]

That is probably true. Another hint for future work: https://robots.thoughtbot.com/git-interactive-rebase-squash-amend-rewriting-history is a good description how to rebase or squash several commits into one.

[lewie]

@J-N-K: Thanks for this Link, have to learn Git. I'm coming from SVN and CVS...

For now I have reset my Fork and commited KNX-Fix. Pull request I have generated.

[teichsta]

you've created a PR for your own fork not for openhab/openhab :-)

[lewie]

@teichsta: Thanks for this note.

I'm a little bit confused! Is this the right one? https://github.com/openhab/openhab/issues/2613 This github generated by itself.

[teichsta]

looks better although the diff is quite unreadable since you seem to reformat the code?!

[lewie]

Hi @teichsta, I see the same Formatting as before in eclipse, did not reformat it, consciously!

You'll get Pointers in new Version: KNXBinding.java: line 168: groupWrite

KNXConnection.java: line 32 line 67 - 72 line 263 line 299 - 308 line 428 - 436

KNXBindingDatapointReaderTask.java: line 14, 15 line 39 line 92 line 103, 104 line 115 -132

Sorry again, I promise improvement.. ;-) Thanks Helmut

[watou]

This may or may not be related to this duplicate events issue, but there is a known weakness in the logic that suppresses the echoing of update events that the binding itself generates, causing them to be echoed back to the underlying system. In KNXBinding.java, the ignoreEventList array keeps a list of update events by concatenating the itemName with the state's string value. In the internalReceiveUpdate method, it consults this list to see if the incoming update should be ignored. All of this appears to work reliability, except in the case of DateTimeType states, since DateTimeType.toString() is not thread-safe, because the underlying shared instance of SimpleDateFormat is not thread-safe. If there are other core types whose toString() methods are not thread-safe, then they might occasionally break as well. The failure causes the remove() from ignoreEventList to fail, since the string that is being checked was created incorrectly, and the update gets echoed back to KNX. This may also cause a very slow memory leak.

This bug was fixed in the Nest and Ecobee bindings, but since I don't have a KNX system, I wanted to let you know that it may be a related issue to this mysterious behavior.

[juelicher]

I have the exact same issue which is described in this thread, although I am using the latest KNX Binding, which should have integrated the fix from this thread.

I suspect, this is because I am using the wiregate as my KNX gateway and therefore the KNX address is 1.1.254 (from the wiregate) and not 0.0.0. I can't change the address in the KNX binding configuration to 1.1.254 because I suspect, this would result in ignoring all telegrams from the wiregate, including the ons not send from openhab.

Maybe someone could confirm, that this is the problem. Are the any solutions, beside using a dedicated IP gateway for openhab?

[steve-bate]

@lewie Since the related PR was merged, can we close this issue?

[lewie]

Yes!