KNX2 stopps working after a while (received disconnect response status 0x21)

shakalandy · June 20, 2018, 7:34pm

I am using the new KNX2 binding and have a strange issue. After some time working the KNX2 binding disconnects from the bus, usually during the first 10-48 hours.

I tested a local KNX interface as well as an MDT IP gateway - same behaviour.

The following error message is logged:

2018-06-20 14:31:48.558 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - connection state response: server could not find active data connect
ion with specified ID (channel 1)
2018-06-20 14:31:58.548 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - connection state response: server could not find active data connect
ion with specified ID (channel 1)
2018-06-20 14:32:08.545 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - connection state response: server could not find active data connect
ion with specified ID (channel 1)
2018-06-20 14:32:18.548 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - connection state response: server could not find active data connect
ion with specified ID (channel 1)
2018-06-20 14:32:28.634 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - received disconnect response status 0x21 (no active data connection
with that ID)
2018-06-20 14:32:28.666 [WARN ] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - close connection - no heartbeat response
2018-06-20 14:32:28.810 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is disconnecting from the KNX bus
2018-06-20 14:32:28.911 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is connecting to the KNX bus
2018-06-20 14:32:28.917 [DEBUG] [binding.knx.internal.client.IPClient] - Establishing connection to KNX bus on localhost:3671 in mode TUNNEL.
2018-06-20 14:32:28.930 [ERROR] [p.KNXnet/IP Tunneling 127.0.0.1:3671] - establishing connection failed, null
2018-06-20 14:32:28.945 [DEBUG] [nx.internal.client.AbstractKNXClient] - Error connecting to the bus: null
java.lang.InterruptedException: null
    at java.lang.Object.wait(Native Method) ~[?:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.waitForStateChange(ConnectionBase.java:541) ~[?:?]
    at tuwien.auto.calimero.knxnetip.ClientConnection.connect(ClientConnection.java:190) ~[?:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.<init>(KNXnetIPTunnel.java:159) ~[?:?]
    at org.openhab.binding.knx.internal.client.IPClient.getConnection(IPClient.java:107) ~[?:?]
    at org.openhab.binding.knx.internal.client.IPClient.createKNXNetworkLinkIP(IPClient.java:90) ~[?:?]
    at org.openhab.binding.knx.internal.client.IPClient.establishConnection(IPClient.java:77) ~[?:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.connect(AbstractKNXClient.java:178) ~[?:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.connectIfNotAutomatic(AbstractKNXClient.java:164) ~[?:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:272) ~[?:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.lambda$1(AbstractKNXClient.java:199) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-06-20 14:32:29.123 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is disconnecting from the KNX bus

Config in knx.things with the local interface:

Bridge knx:ip:bridge [
        ipAddress="localhost",
        portNumber=3671,
        localIP="192.168.188.28",
        type="TUNNEL",
        readingPause=50,
        responseTimeout=10,
        readRetriesLimit=3,
        autoReconnectPeriod=1,
        localSourceAddr="0.0.0"
]
{
    Thing device ug_sa1 "KNX SA 1 16-f UG (1.1.1)" @ "KNX" [
        address="1.1.1",
        pingInterval=300
] {

what is going on here?
Stopping an starting the bundle again usually reconnects OH2 to the KNX bus.

Recreate config as mentioned in [SOLVED] OH2.3 with KNX2: Stopped receiving KNX-status-updates after upgrade from OH2.2 with KNX1 ?
Reinstall the binding?

Thanks for your help.

Dim · June 21, 2018, 4:19am

did you try routing also and have the same issues?

are you using knxd on the localhost? it seems that knxd is losing the connection to the bus. How do you connect to the bus when using knxd?

shakalandy · June 21, 2018, 8:27am

i tried routing but it didn’t work, came across the “use TUNNEL if routing does not work” recommendation.
I am using a local KNX TUPUART Interface in that case, connections works. Host is a beaglebone.

I have the same problem when i use the remote IP of the external IP Interface.

shakalandy · June 24, 2018, 4:26pm

Tried several different routing configs now, can’t get it working.

Local knxd, version 0.14.25-1
configured via /etc/knxd.conf:

KNXD_OPTS="-e 0.0.1 -E 0.0.2:9 -D -T -R -A multi-port=true -S -b tpuarts:/dev/ttyKNX1"

knxd ist up and running:

tcp6       0      0 127.0.0.1:6720          127.0.0.1:50914         ESTABLISHED 6865/knxd

i can reach the port 6720 on the host via “telnet 192.168.188.10” - which is the devices ip address

i set knx.things to:

    Bridge knx:ip:bridge [
	portNumber=6720,
	type="ROUTER",
	readingPause=50,
	responseTimeout=10,
	readRetriesLimit=3,
	autoReconnectPeriod=1,
	localSourceAddr="0.0.1"
]

openhab tries to connect to the multicast port - connection times out.
What am i doing wrong?
Tried “localip: 192.168.188.10” as well - no success.

Thanks very much!

Dim · June 25, 2018, 1:46pm

post the output of netstat -i from your linux host running the knxd plz

shakalandy · June 25, 2018, 5:50pm

netstat -i
Kernel Interface table
Iface      MTU    RX-OK RX-ERR RX-DRP RX-OVR    TX-OK TX-ERR TX-DRP TX-OVR Flg
eth0      1500  1162785      0      0 0        418682      0      0      0 BMRU
lo       65536   410328      0      0 0        410328      0      0      0 LRU
usb0      1500        0      0      0 0             0      0      0      0 BMU
usb1      1500        0      0      0 0             0      0      0      0 BMU

 netstat -natp  | grep knx
tcp6       0      0 127.0.0.1:6720          127.0.0.1:53236         ESTABLISHED 16406/knxd

telnet 192.168.188.10 6720
Trying 192.168.188.10...
Connected to 192.168.188.10.
Escape character is '^]'

it can connect to the knxd from localhost via ip and from a remote host.
Don’t know why it is showing only 127.0.0.1 there - ipv6 problem?

Dim · June 25, 2018, 9:43pm

I don’t use knxd so I can’t help much
the tcp6 entry looks ok. it listens to both v4 & v6.

your ethernet interface has the M flag (for multicast), so that’s ok also…
not sure what could be wrong. play with different knxd settings maybe?

most use tcp port 3671 (applies to both tunneling and routing)

shakalandy · June 26, 2018, 8:08pm

KNXD uses 6720 per default. Strange thing.
I switched back to using the IP Interface from MDT. Although i have a similar problem there since i switched to the knx2 binding of OH. It also stops working but with a different error.
Worked with the knx1 binding before without problems
Will update here with the new error.

shakalandy · June 28, 2018, 6:56pm

Similar problem when using the Remote MDT interface.

2018-06-27 22:04:43.675 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is disconnecting from the KNX bus
2018-06-27 22:04:43.688 [DEBUG] [nx.internal.client.AbstractKNXClient] - The KNX network link was detached from the process communicator
2018-06-27 22:04:43.706 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is connecting to the KNX bus
2018-06-27 22:04:43.715 [DEBUG] [binding.knx.internal.client.IPClient] - Establishing connection to KNX bus on 192.168.188.29:3671 in mode TUNNEL.
2018-06-27 22:04:43.746 [ERROR] [net/IP Tunneling 192.168.188.29:3671] - establishing connection failed, null
2018-06-27 22:04:43.760 [DEBUG] [nx.internal.client.AbstractKNXClient] - Error connecting to the bus: null
java.lang.InterruptedException: null
        at java.lang.Object.wait(Native Method) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ConnectionBase.waitForStateChange(ConnectionBase.java:541) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ClientConnection.connect(ClientConnection.java:190) ~[?:?]
        at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.<init>(KNXnetIPTunnel.java:159) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.getConnection(IPClient.java:107) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.createKNXNetworkLinkIP(IPClient.java:90) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.establishConnection(IPClient.java:77) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.connect(AbstractKNXClient.java:178) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.connectIfNotAutomatic(AbstractKNXClient.java:164) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:272) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.lambda$1(AbstractKNXClient.java:199) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-06-27 22:04:43.991 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:bridge is disconnecting from the KNX bus

any ideas @Dim ?
Thanks.

config is this now:

Bridge knx:ip:bridge [
        ipAddress="192.168.188.29",
        portNumber=3671,
        localIP="192.168.188.28",
        type="TUNNEL",
        readingPause=50,
        responseTimeout=10,
        readRetriesLimit=3,
        autoReconnectPeriod=1
]

Stopping and restarting the KNX bundle solves the problem. For some hours at least.
The old knx1 binding worked with this hardware and gateway setup without problems.

Dim · June 28, 2018, 7:53pm

I don’t know what could be wrong…configs look good

It could be a bug with the binding, it could be a comms issue…

Double check networking stuff between the OH2 host and the MDT interface (swap UTP cables, Ports on the Switch, ethernet card on the host, go direct for testing if possible). What hardware are you running OH2 on? (rPi or something else?).
Can you test the KNX2 binding connectivity on another host running OH2 ?

Try to enable TRACE on the tuwien.auto.calimero also to see if anything interesting comes up.

shakalandy · June 29, 2018, 10:41pm

Hardware is the same as with OH2 and knx1 (beaglebone connected to GBIT Switch).
With knx1 it just worked.

2018-06-29 21:02:29.078 [DEBUG] [nx.internal.client.AbstractKNXClient] - The KNX network link was detached from the process communicator
2018-06-29 21:02:29.081 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:MDT is disconnecting from the KNX bus
2018-06-29 21:02:29.095 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:MDT is connecting to the KNX bus
2018-06-29 21:02:29.292 [DEBUG] [binding.knx.internal.client.IPClient] - Establishing connection to KNX bus on 192.168.188.29:3671 in mode TU
NNEL.
2018-06-29 21:02:29.085 [DEBUG] [.knx.handler.AbstractKNXThingHandler] - An error occurred while testing the reachability of a thing 'knx:dev
ice:MDT:ug_sa1'
tuwien.auto.calimero.link.KNXLinkClosedException: link closed
        at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:348) ~[?:?]
        at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
        at tuwien.auto.calimero.mgmt.TransportLayerImpl.sendData(TransportLayerImpl.java:372) ~[?:?]
        at tuwien.auto.calimero.mgmt.ManagementClientImpl.send(ManagementClientImpl.java:797) ~[?:?]
        at tuwien.auto.calimero.mgmt.ManagementClientImpl.sendWait2(ManagementClientImpl.java:824) ~[?:?]
        at tuwien.auto.calimero.mgmt.ManagementClientImpl.readDeviceDesc(ManagementClientImpl.java:447) ~[?:?]
        at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.isAddressOccupied(ManagementProceduresImpl.java:310) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.isReachable(AbstractKNXClient.java:338) ~[?:?]
        at org.openhab.binding.knx.handler.AbstractKNXThingHandler.pollDeviceStatus(AbstractKNXThingHandler.java:144) ~[?:?]
        at org.openhab.binding.knx.handler.AbstractKNXThingHandler.lambda$1(AbstractKNXThingHandler.java:184) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-06-29 21:02:29.334 [ERROR] [net/IP Tunneling 192.168.188.29:3671] - establishing connection failed, null
2018-06-29 21:02:29.345 [DEBUG] [nx.internal.client.AbstractKNXClient] - Error connecting to the bus: null
java.lang.InterruptedException: null
        at java.lang.Object.wait(Native Method) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ConnectionBase.waitForStateChange(ConnectionBase.java:541) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ClientConnection.connect(ClientConnection.java:190) ~[?:?]
        at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.<init>(KNXnetIPTunnel.java:159) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.getConnection(IPClient.java:107) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.createKNXNetworkLinkIP(IPClient.java:90) ~[?:?]
        at org.openhab.binding.knx.internal.client.IPClient.establishConnection(IPClient.java:77) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.connect(AbstractKNXClient.java:178) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.connectIfNotAutomatic(AbstractKNXClient.java:164) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:272) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.lambda$1(AbstractKNXClient.java:199) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:?]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
2018-06-29 21:02:29.579 [DEBUG] [nx.internal.client.AbstractKNXClient] - Bridge knx:ip:MDT is disconnecting from the KNX bus

:

enabled debug - not really helpful - right?
considering to migrate back to KNX1 binding now

shakalandy · July 4, 2018, 9:24pm

Completely purged my openhab2 installation, wiped all configs, etc.
reinstalled a fresh 2.3 - now everything seems to be fine with using the knx2 binding
No KNX disconnect any more for 4 days now.

i hope that’s it!

markus_pfleger · July 10, 2018, 5:58am

I have the same problem. Starting openHab everything works fine but after a few hours it seems to disconnect.

The reinstall thing sounds interesting. Is everything still working for you now?
Hm, maybe I start deleting caches ant temp files first…

shakalandy · July 10, 2018, 8:16am

Jep, everything still working. I completely wiped everything, in my old installation i had some config files from knx1 binding left - thought that would be no problem cause the binding was inactive.

markus_pfleger · July 13, 2018, 7:40pm

Thanks, also reinstalled openhab and it seems to work fine. No problems for 24h, never had that since using the knx2 binding.

Would be really interesting what causes the problem. I uninstalled the old knx binding, cleared the cache,… but it didn’t help. Uninstall and a fresh openhab2 install and it seems to work fine.

markus_pfleger · August 6, 2018, 5:49am

Wanted to add some information. The clean openh2 installation worked fine, so no more disconnects from knx.

However, after about 3 weeks I found out that querying of my Kostal Pico inverter does not work anymore because I forgot to reinstall the HTTP binding. After reinstalling it it seems the problem reoccurred. The next day openhab disconnected again. I removed the HTTP binding and everything works fine.

I have to do another check, might have been a coincidence, but maybe there is some side effect between those bindings…

andrzej_szymkowicz · September 10, 2018, 6:21am

I have several fresh OH 2.3 installations and have the same problem. For some of them problem appeared after few months of work and for others after few days.
For now I have workaround - rule that restarts bundle when knx ip bridge thing changed status to UNINITIALIZED. Since KNX binding is the most important to me I’m interested in the final solution.

Are you using file thing configuration or PaperUI?

markus_pfleger · September 10, 2018, 6:46am

I am using file configurations for nearly everything. So the things as well as all my items.

@ andrzej_szymkowicz could you paste the rule you are using to restart the bundle?

andrzej_szymkowicz · September 10, 2018, 7:17am

Rule is simple:
rule “KNXThingRestart”
when
Thing “knx:ip:bridge” changed to UNINITIALIZED
then
systemKNXBundleRestart.sendCommand(ON)
end

but first you need to configure auto login to karat console by openhab user and create command thing and item:

Karaf console autologin:
mkdir /var/lib/openhab2/.ssh
cd /var/lib/openhab2
sudo chown -R openhab:openhab .ssh
cd /var/lib/openhab2/.ssh
sudo -u openhab ssh-keygen -t rsa -f openhab.id_rsa
sudo chmod 400 openhab.id_rsa
sudo -u openhab nano config
Host console
hostname localhost
port 8101
user openhab
IdentityFile /var/lib/openhab2/.ssh/openhab.id_rsa

sudo chmod 400 config

Import the public key (sudo -u openhab cat openhab.id_rsa.pub) into /var/lib/openhab2/etc/keys.properties like
openhab=AAAAB3NzaC1kc3M…XWKpeyW789IBpcZfyYQ=,g:admingroup
Be aware that the leading “ssh-key” and trailing “user@server” has to be omitted.

sudo -u openhab ssh console

Command Thing
Name: KNX Bundle Restart
ThingID: KNXBundleRestart
Command: ssh console bundle:restart org.openhab.binding.knx
Interval: 0
Item:
Switch systemKNXBundleRestart “KNX bundle” { channel=“exec:command:KNXBundleRestart:run”}

markus_pfleger · September 11, 2018, 7:46am

Thanks a lot!