KNX Item not triggering rule

Christian_Huck · April 9, 2017, 10:34am

Hi,

hopefully this is the right spot to post problems - if not just let me know.

I am using the KNX-Binding with OpenHab2.

Item Config
Switch Sammelklingel_Mobotix "Sammelklingel Ausgang Mobotix" () { knx="<0/4/2"}

This item is “read only” for openhab.It should only listen for events.

Rule
Based on this item I have a simple rule which should trigger when the item value is switched to ON (by the KNX Bus)
So very simple:

rule 'lueftung'
when
    Item Sammelklingel_Mobotix changed from OFF to ON
then
  logInfo('klingel', 'Es hat geklingelt.')

Problem
The rule does NOT trigger. Very rarely it works(can’t tell exactly when). But in any case after a OH restart it stops working, which sucks.

Analysis
What I’ve checked so far is that the item actually GETS changed in openhab. I’ve used the openhab console to verify that like this:

openhab> smarthome:status Sammelklingel_Mobotix
OFF

When the item gets switched by KNX I can see an ‘ON’ value here for 2 seconds. So openHab sees this change which is good but I don’t understand why my rule is not reliable triggering.

KNX bind config
My binding config is as simple as this:

ip=224.0.23.12
knx:ignorelocalevents=true
type=ROUTER
localIp=192.168.xxx.yyy

Besides this problem the KNX stuff is perfectly working. All shutters, heatings, switches etc. are o.k.

Can anybody tell me what my problem is and why this #+’*! rule is not triggering ?

THANKS IN ADVANCE !

rossko57 · April 9, 2017, 11:34am

The trigger is specific OFF to ON. It would not trigger, for example, after a restart where the item is undefined…

Christian_Huck · April 9, 2017, 6:43pm

Well…
As stated I can see on OFF state switching to an ON state in the console.

Besides that I initialize the item with an ‘<’ sign, which - I thought - tells OpenHab to fetch the item status on init.

So I don’t think it’s uninitialized.

Any other thoughts on this ? More information I can provide ?

rossko57 · April 9, 2017, 6:53pm

For debug purposes, trigger the rule on simply changed. Add a logInfo to report current Item.state to see what is going on.

Udo_Hartmann · April 9, 2017, 7:18pm

Please also check received command ON and/or received update ON as triggers.

Christian_Huck · April 9, 2017, 7:56pm

It’s odd…

Nothing works. I’ve tried

received update ON
changed
received command ON

The behaviour is:

OpenHab restart
Item Value is NULL
KNX binding gets loaded
Value changes to OFF (which is correct)
trigger from KNX bus is send (ON)
OpenHab Console shows the value change for 2 seconds to ON - then back to OFF
The rule does not trigger

The interesting thing: When I change the rule to some other trigger option - it suddenly works until the next restart.

Christian_Huck · April 9, 2017, 8:02pm

Here is the KNX Debug Log when I press the button and it does NOT work:

2017-04-09 21:59:10.006 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 15.15.255
2017-04-09 21:59:10.012 [INFO ] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send message to 0/4/1, wait for confirmation
2017-04-09 21:59:10.013 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: cEMI L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 81
2017-04-09 21:59:10.015 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: add to multicast loopback frame buffer: L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 81
2017-04-09 21:59:10.021 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: sending cEMI frame seq 0, non-blocking, attempt 1 (channel 0) 06 10 05 30 00 11 29 00 bc e0 00 01 04 01 01 00 81
2017-04-09 21:59:10.022 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send to 0/4/1 succeeded
2017-04-09 21:59:10.031 [DEBUG] [tuwien.auto.calimero                ] - process 224.0.23.12:3671: group write to 0/4/1 succeeded
2017-04-09 21:59:10.032 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: discard multicast loopback cEMI frame: L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 81
2017-04-09 21:59:10.074 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 1.0.52
2017-04-09 21:59:10.079 [INFO ] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send message to 0/4/2, wait for confirmation
2017-04-09 21:59:10.080 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: cEMI L-Data.ind from 0.0.1 to 0/4/2, low priority hop count 6 tpdu 00 81
2017-04-09 21:59:10.081 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: add to multicast loopback frame buffer: L-Data.ind from 0.0.1 to 0/4/2, low priority hop count 6 tpdu 00 81
2017-04-09 21:59:10.082 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: sending cEMI frame seq 0, non-blocking, attempt 1 (channel 0) 06 10 05 30 00 11 29 00 bc e0 00 01 04 02 01 00 81
2017-04-09 21:59:10.082 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send to 0/4/2 succeeded
2017-04-09 21:59:10.083 [DEBUG] [tuwien.auto.calimero                ] - process 224.0.23.12:3671: group write to 0/4/2 succeeded
2017-04-09 21:59:10.086 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: discard multicast loopback cEMI frame: L-Data.ind from 0.0.1 to 0/4/2, low priority hop count 6 tpdu 00 81

Does not make much sense to me.

The GA which is the trigger is 0/4/2. The Physical Address of the sending KNX device is 1.0.52(appears in the log)

Christian_Huck · April 9, 2017, 8:05pm

I think this guy has a similiar issue which was never solved:
https://community.openhab.org/t/knx-status-updates-at-startup/17586/6

rossko57 · April 9, 2017, 9:17pm

I’d look in Openhab log for state changes to the Item. Guessing they won’t be there - not on OH bus, no rule trigger.

Christian_Huck · April 10, 2017, 6:42am

I can see the state change from OFF to ON and OFF again in the OH console.

Sried · April 10, 2017, 2:57pm

Maybe it´s just not in your post: The closing “end” of the then-block is in your rules file?

Christian_Huck · April 10, 2017, 2:58pm

correct. It is just a snippet - not the full rule.

rossko57 · April 10, 2017, 7:37pm

So you haven’t seen the Item being updated in the OH log.

Sried · April 11, 2017, 3:28pm

I guess the item is a door bell? Then I would assume the behaviour going into state ON for 2 sec and then falling back to OFF as logical. Could that behaviour be ok? Did you monitor the KNX bus with ETS or a similar tool?
I did often struggle with the file coding. I work from Windows and often the file coding UTF-8 is not recognized and the file gets saved in ANSI coding. Then the rule is parsed without error but it is somehow not recognized.
I´m now using notepad++ as an editor and turned on UTF-8 w/o BOM as default.
Maybe you have a similar problem? Pls check the file coding.

Christian_Huck · April 12, 2017, 7:19am

HI rossko57,

I’ve not check then OH log yet. I will do that.
I thought it would be enough verification to see the value change in the OH console.
I will take a look in the logs asap.

Christian_Huck · April 12, 2017, 7:21am

Hi Sried,

you’re right. Down the line it’s a doorbell button which is pressed and released. That is correct.

I am on Linux(both - workstation and OH server) so I assume no encoding issue…

rossko57 · April 12, 2017, 10:31am

It’s a really good idea when fault finding. Well worth also checking the load of the .rules file for e.g. a parsing error.

Christian_Huck · April 22, 2017, 11:22am

o.k. - back the the required information:

Here is the relevant ETS Busmonitor part:

Here is the corresponding openhab log with KNX DEBUG enabled:

2017-04-22 12:47:25.715 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 1.0.52
2017-04-22 12:47:26.991 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 1.0.63
2017-04-22 12:47:26.997 [INFO ] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send message to 0/4/3, wait for confirmation
2017-04-22 12:47:26.998 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: cEMI L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 81
2017-04-22 12:47:26.999 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: add to multicast loopback frame buffer: L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 81
2017-04-22 12:47:27.002 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: sending cEMI frame seq 0, non-blocking, attempt 1 (channel 0) 06 10 05 30 00 11 29 00 bc e0 00 01 04 03 01 00 81
2017-04-22 12:47:27.005 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send to 0/4/3 succeeded
2017-04-22 12:47:27.005 [DEBUG] [tuwien.auto.calimero                ] - process 224.0.23.12:3671: group write to 0/4/3 succeeded
2017-04-22 12:47:27.006 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: discard multicast loopback cEMI frame: L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 81
2017-04-22 12:47:27.466 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 15.15.255
2017-04-22 12:47:27.472 [INFO ] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send message to 0/4/1, wait for confirmation
2017-04-22 12:47:27.473 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: cEMI L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 80
2017-04-22 12:47:27.473 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: add to multicast loopback frame buffer: L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 80
2017-04-22 12:47:27.475 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: sending cEMI frame seq 0, non-blocking, attempt 1 (channel 0) 06 10 05 30 00 11 29 00 bc e0 00 01 04 01 01 00 80
2017-04-22 12:47:27.475 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send to 0/4/1 succeeded
2017-04-22 12:47:27.476 [DEBUG] [tuwien.auto.calimero                ] - process 224.0.23.12:3671: group write to 0/4/1 succeeded
2017-04-22 12:47:27.477 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: discard multicast loopback cEMI frame: L-Data.ind from 0.0.1 to 0/4/1, low priority hop count 6 tpdu 00 80
2017-04-22 12:47:29.387 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 1.1.3
2017-04-22 12:47:29.945 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: indication from 1.0.63
2017-04-22 12:47:29.950 [INFO ] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send message to 0/4/3, wait for confirmation
2017-04-22 12:47:29.951 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: cEMI L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 80
2017-04-22 12:47:29.955 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: add to multicast loopback frame buffer: L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 80
2017-04-22 12:47:29.955 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: sending cEMI frame seq 0, non-blocking, attempt 1 (channel 0) 06 10 05 30 00 11 29 00 bc e0 00 01 04 03 01 00 80
2017-04-22 12:47:29.956 [DEBUG] [tuwien.auto.calimero                ] - calimero.link.224.0.23.12:3671: send to 0/4/3 succeeded
2017-04-22 12:47:29.957 [DEBUG] [tuwien.auto.calimero                ] - process 224.0.23.12:3671: group write to 0/4/3 succeeded
2017-04-22 12:47:29.959 [DEBUG] [tuwien.auto.calimero                ] - KNXnet/IP Routing 224.0.23.12:3671: discard multicast loopback cEMI frame: L-Data.ind from 0.0.1 to 0/4/3, low priority hop count 6 tpdu 00 80

As you can see at 12:47:28,071 the KNX Group address 0/4/3 received an ‘ON’ from the device 1.0.63(KNX actuator) in the KNX Monitor.

In the OH log I can see an entry ‘indication from 1.0.63’ a bit later.
Anyways - as stated already I can the that OH received this information since I can see the value change in the OH console:

                          __  _____    ____      
  ____  ____  ___  ____  / / / /   |  / __ )     
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  | 
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /      
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/     
    /_/                        2.0.0
                               Release Build   

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.
openhab> smarthome:status Sammelklingel_Mobotix
OFF
openhab> smarthome:status Sammelklingel_Mobotix
ON
openhab> smarthome:status Sammelklingel_Mobotix
ON
openhab> smarthome:status Sammelklingel_Mobotix
ON
openhab> smarthome:status Sammelklingel_Mobotix
OFF

So - I think that is an undisputed fact that OH does receive the event.

Now back to the issue: Why is the rule not triggering ? Is this a bug ?

Christian_Huck · April 22, 2017, 11:38am

WAAAAAAAHHHHHHHHH…

this rule was named ‘lueftung’ which is wrong…

There was another rule with the same name ‘lueftung’

I changed it to ‘klingel’. It’s working now !

Improvment suggestion: print an ERROR in log for rules with the same name