OH 2.3 Huge delay between actions - 6 second (was also on OH 1.x)

[aviperi]

I’m running OH 2.3 over RPi3 with KNX binding

I upgraded to OH 2.3 as I faced huge delays between actions (~6 sec) on OH 1.9.
I upgrade successfully making all adjustments and the system is working stable. However, I’m facing delay (~6 sec) between sequential actions.

This is the KNX configuration at the KNX.things file applies to all things:

Bridge knx:ip:WEINZIERL771 "KNX IP BAOS 771" @ "KNX" [
            type="TUNNEL",
            ipAddress="10.0.0.24",
            portNumber=3671,
            localIp="10.0.0.30",
            readingPause=50,
            responseTimeout=10,
            readRetriesLimit=3,
            autoReconnectPeriod=1,
            localSourceAddr="1.2.200" ]
{

I created virtual switch that turns ON->OFF->ON a specific light. I added sendNotification between each action with time stamp. I have noticed that the notifications are with almost no delay, however the light is turning ON->OFF->ON with a ~6 second delay.
I also checked the events.log file and it is the same almost no delay:

2018-11-23 17:41:11.512 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2018-11-23 17:41:11.532 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command OFF
2018-11-23 17:41:11.538 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2

But still the light has delay with the operation again ~6 sec between ON and OFF

Any suggestions?

I also have some warnings on the openhab.log file during running the system:

2018-11-23 17:33:48.150 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/2/50 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
        at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
        at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
        at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
        at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
        at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
        at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
        at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
        at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
        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:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]

This warning is almost every 3 seconds

And I have another warning from time to time:

2018-11-23 17:33:45.081 [WARN ] [calimero.mgmt.TL 10.0.0.24:3671     ] - disconnected not gracefully (timeout)
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->1.1.1 L_Data.req, system priority hop count 6 repeat, tpdu 81
        at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
        at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
        at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
        at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
        at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
        at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
        at tuwien.auto.calimero.mgmt.TransportLayerImpl.sendDisconnect(TransportLayerImpl.java:612) ~[?:?]
        at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnectIndicate(TransportLayerImpl.java:600) ~[?:?]
        at tuwien.auto.calimero.mgmt.TransportLayerImpl.disconnect(TransportLayerImpl.java:342) ~[?:?]
        at tuwien.auto.calimero.mgmt.Destination.destroy(Destination.java:371) ~[?:?]
        at tuwien.auto.calimero.mgmt.Destination.close(Destination.java:383) ~[?:?]
        at tuwien.auto.calimero.mgmt.ManagementProceduresImpl.isAddressOccupied(ManagementProceduresImpl.java:311) ~[?:?]
        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:1142) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
        at java.lang.Thread.run(Thread.java:745) [?:?]

Any Ideas?

Thanks

[Dim (Angelos)]

@aviperi

I upgraded to OH 2.3 as I faced huge delays between actions (~6 sec) on OH 1.9.

You mean: “I upgraded from KNXv1 (1.9) to KNXv2 (2.3) Binding on openHAB 2.3.0 Stable”

How long were you running KNXv1 with this delay? that’s unusable

Regarding the KNX IP BAOS 771 Interface:

1. Is your KNX Bus overloaded? What does ETS say? Are your normal KNX bush-buttons displaying similar behavior (slow response) ?
2. What is the Individual Address (IA aka PA) of the Interface?
3. What is the IA Range for the clients?
4. Does it have any manufacturer specific configuration options on it?
   For example, on my GIRA IP Router, when I was using it as a Tunneling Interface, I was experiencing reply timeouts like you until I disabled “Reliable Comms” on the device (some proprietary stuff from GIRA).

Your KNXv2 Binding config looks good. Validate KNXnet/IP overall and it should work.

Since your comms are not stable, increase a bit autoReconnectPeriod to 10 secs in order to avoid spamming the BAOS (does the BAOS have any CPU/Mem statistics on it?)

It is strange that the telegram finally succeeds to operate the light (after ~6 secs of delay).
It looks like a KNXnet/IP conf problem.

[aviperi]

Thanks Dim for your response.

I was running the OH 1.9 for long period with the delay. I have noticed the delay first as I have two rollershutter one next to the other that I used one switch on OH to open/close both. When I opened/closed them there was always a gap between them. I have two physical KNX push button for each rollershutter and when I press them together, both rollershutter are open/close at the same time.

Regarding your questions, I didn’t configure the KNX IP BAOS 771 Interface. It gets is IP address from the DHCP server and it is used as tunnel. I’m not familiar with the terminology (IA, IA Range) as it was done by 3rd party. It will be appreciate if you let me know how to get these parameters

I increased the autoReconnectPeriod to 10 and i’m still getting the same results - actually the delay is almost 12 seconds between the actions (also when autoReconnectPeriod was 1 sec) as you can see in the logs (vent.ItemStateChangedEvent)

2018-11-24 18:14:08.575 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2018-11-24 18:14:08.597 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command OFF
2018-11-24 18:14:08.610 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2018-11-24 18:14:11.359 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from OFF to ON
2018-11-24 18:14:23.475 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from ON to OFF
2018-11-24 18:14:35.631 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from OFF to ON

Thanks

[aviperi]

Any suggestions?

[Dim (Angelos)]

The communications between OH2.3 with KNXv2 Binding and your Tunneling interface are (very) unreliable currently.
This is not normal… Telegrams originating from OH2 should take milliseconds to arrive and be processed, not seconds.

To debug this, you need to check the configs of the IP Tunneling interface by browsing to its IP Address.
Can you post some screenshots from the BAOS configs?

I would also try to reserve the IP Address for this device on my DHCP server so that it doesn’t change over time.

@aviperi

localIp=“10.0.0.30”

by the way: I saw that you are using a Class A Subnet for your LAN… what is your subnet mask?

[aviperi]

Thanks for the prompt response

I don’t know how to communicate/config the BAOS. When I’m trying to connect to it (using web) I’m getting its MAC address. I’ll try to contact the company for more information.

Regarding the subnet mask it is: 255.255.255.0

Thanks

[Dim (Angelos)]

I am not sure if it offers web based configuration (obviously it doesn’t )
Your only option then would be to use ETS to see and modify its configuration

[aviperi]

Do I need special tool for it? I’m not familiar with how to config the KNX staff. I got everything ready from the technician and I only connected the Openhab to it.

I checked with Wireshark and I saw that the packets of my test are sent with the delay. I didn’t see any retries but I saw also some randomized request that I didn’t initiate - strange

[Dim (Angelos)]

@aviperi

I checked with Wireshark and I saw that the packets of my test are sent with the delay.

This delay in sending out the UDP packets from your OH2 host could be due to 2 reasons:

1. The binding has detected a timeout, stays disconnected and re-tries later (most likely)
2. There is some other problem with your OH2 installation

can you try to enable TRACE log levels for both the binding and the underlying I/O library:
using OH2 console:

log:set TRACE org.openhab.binding.knx
log:set TRACE calimero

upload some logs here to check
(remember to set them back to INFO when you collect some logs)

@aviperi

Do I need special tool for it?

Yes, it’s called: ETS (your installer will have it)
It’s expensive
Try to debug OH2 before you start spending money on installer visits and/or purchase of ETS license

[aviperi]

Thanks again for your help.

I only included the information before and after the light turned ON->OFF->ON
I’m attaching the log (it is a bit big ). As it is big file - I’m splitting it into parts and will send few messages:

openhab.log before triggering the test:

2018-11-28 10:28:22.509 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/22: no confirmation reply received for 1.2.200->7/1/22 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:22.561 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/2/8
2018-11-28 10:28:22.564 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/2/8 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:22.567 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 159, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 9f 00 11 00 bc e0 12 c8 3a 08 01 00 00
2018-11-28 10:28:22.573 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 159 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:22.576 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 22 (channel 9) cEMI 29 00 bc e0 12 c8 3a 08 01 00 00
2018-11-28 10:28:22.578 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/2/8 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:22.578 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/2/8'
2018-11-28 10:28:22.581 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' received a Group Read Request telegram from '1.2.200' for destination '7/2/8'
2018-11-28 10:28:22.638 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 23 (channel 9) cEMI 29 00 bc e0 11 03 3a 08 01 00 40
2018-11-28 10:28:22.641 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.3->7/2/8 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:22.641 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.3' to '7/2/8'
2018-11-28 10:28:22.645 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' received a Group Write telegram from '1.1.3' for destination '7/2/8'
2018-11-28 10:28:22.651 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' processes a Group Write telegram for destination '7/2/8' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B4:Ch_B4_H'
2018-11-28 10:28:22.654 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:25.573 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/2/8 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:25.622 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/2/8: no confirmation reply received for 1.2.200->7/2/8 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:25.674 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/2
2018-11-28 10:28:25.676 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/2 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:25.677 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 160, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a0 00 11 00 bc e0 12 c8 39 02 01 00 00
2018-11-28 10:28:25.682 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 160 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:25.685 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 24 (channel 9) cEMI 29 00 bc e0 12 c8 39 02 01 00 00
2018-11-28 10:28:25.687 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/2'
2018-11-28 10:28:25.687 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/2 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:25.689 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Read Request telegram from '1.2.200' for destination '7/1/2'
2018-11-28 10:28:25.751 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 25 (channel 9) cEMI 29 00 bc e0 11 01 39 02 01 00 40
2018-11-28 10:28:25.753 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.1' to '7/1/2'
2018-11-28 10:28:25.753 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.1->7/1/2 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:25.754 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Write telegram from '1.1.1' for destination '7/1/2'
2018-11-28 10:28:25.757 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' processes a Group Write telegram for destination '7/1/2' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B1:Ch_B1_B'
2018-11-28 10:28:25.758 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:28.682 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/2 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:28.731 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/2: no confirmation reply received for 1.2.200->7/1/2 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:28.784 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/23
2018-11-28 10:28:28.787 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/23 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:28.791 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 161, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a1 00 11 00 bc e0 12 c8 39 17 01 00 00
2018-11-28 10:28:28.797 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 161 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:28.800 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 26 (channel 9) cEMI 29 00 bc e0 12 c8 39 17 01 00 00
2018-11-28 10:28:28.803 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/23'
2018-11-28 10:28:28.806 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Read Request telegram from '1.2.200' for destination '7/1/23'
2018-11-28 10:28:28.806 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/23 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:28.852 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 27 (channel 9) cEMI 29 00 bc e0 11 35 39 17 01 00 40
2018-11-28 10:28:28.856 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.53->7/1/23 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:28.857 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.53' to '7/1/23'
2018-11-28 10:28:28.861 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Write telegram from '1.1.53' for destination '7/1/23'
2018-11-28 10:28:28.865 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' processes a Group Write telegram for destination '7/1/23' for channel 'knx:device:WEINZIERL771:MDT_AKS_0816_B2:Ch_B2_C'
2018-11-28 10:28:28.869 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001

I’m also attaching the events.log so it will be easy to synchronize with the time stamp:

2018-11-28 10:28:31.714 [ome.event.ItemCommandEvent] - Item 'gActiveTestRule' received command ON
2018-11-28 10:28:31.769 [vent.ItemStateChangedEvent] - gActiveTestRule changed from OFF to ON
2018-11-28 10:28:35.358 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2018-11-28 10:28:35.369 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command OFF
2018-11-28 10:28:35.400 [ome.event.ItemCommandEvent] - Item 'B5_A_1F_WORK_READ_LIGHT' received command ON
2018-11-28 10:28:38.103 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from OFF to ON
2018-11-28 10:28:50.253 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from ON to OFF
2018-11-28 10:29:02.478 [vent.ItemStateChangedEvent] - B5_A_1F_WORK_READ_LIGHT changed from OFF to ON

Thanks

[aviperi]

Openhab.log after the the light turned on last time:

2018-11-28 10:29:05.453 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:29:05.461 [DEBUG] [nx.internal.client.AbstractKNXClient] - Value 'ON' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81. Will retry.
2018-11-28 10:29:05.464 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2018-11-28 10:29:05.466 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 173, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 ad 00 11 00 bc e0 12 c8 39 1b 01 00 00
2018-11-28 10:29:05.473 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 173 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:29:05.477 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 48 (channel 9) cEMI 29 00 bc e0 12 c8 39 1b 01 00 00
2018-11-28 10:29:05.481 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/27'
2018-11-28 10:29:05.481 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/27 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:29:05.484 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Read Request telegram from '1.2.200' for destination '7/1/27'
2018-11-28 10:29:05.530 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 49 (channel 9) cEMI 29 00 bc e0 11 35 39 1b 01 00 40
2018-11-28 10:29:05.533 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.53->7/1/27 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:29:05.533 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.53' to '7/1/27'
2018-11-28 10:29:05.543 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Write telegram from '1.1.53' for destination '7/1/27'
2018-11-28 10:29:05.548 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' processes a Group Write telegram for destination '7/1/27' for channel 'knx:device:WEINZIERL771:MDT_AKS_0816_B2:Ch_B2_G'
2018-11-28 10:29:05.551 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:29:07.582 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending connection state request, attempt 1
2018-11-28 10:29:08.473 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/27 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:29:08.523 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/27: no confirmation reply received for 1.2.200->7/1/27 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:29:08.527 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 174, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 ae 00 11 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:29:08.539 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 174 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:29:08.543 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 50 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:29:08.545 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:29:08.548 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:29:08.548 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:29:08.551 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:29:08.554 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:29:08.576 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/2/21
2018-11-28 10:29:08.579 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:29:11.540 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:29:11.545 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'ON' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81. Giving up now.
2018-11-28 10:29:11.546 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 175, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 af 00 11 00 bc e0 12 c8 3a 15 01 00 00
2018-11-28 10:29:11.552 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 175 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:29:11.554 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 51 (channel 9) cEMI 29 00 bc e0 12 c8 3a 15 01 00 00
2018-11-28 10:29:11.555 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/2/21 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:29:11.555 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/2/21'
2018-11-28 10:29:11.557 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Read Request telegram from '1.2.200' for destination '7/2/21'
2018-11-28 10:29:11.549 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81

[aviperi]

The openhab.logs during the test when the light turn On->OFF->ON (Part I)

2018-11-28 10:28:31.797 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/23 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:31.829 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/23: no confirmation reply received for 1.2.200->7/1/23 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:31.882 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/3
2018-11-28 10:28:31.884 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/3 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:31.886 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 162, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a2 00 11 00 bc e0 12 c8 39 03 01 00 00
2018-11-28 10:28:31.892 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 162 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:31.894 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 28 (channel 9) cEMI 29 00 bc e0 12 c8 39 03 01 00 00
2018-11-28 10:28:31.896 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/3 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:31.896 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/3'
2018-11-28 10:28:31.899 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Read Request telegram from '1.2.200' for destination '7/1/3'
2018-11-28 10:28:31.957 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 29 (channel 9) cEMI 29 00 bc e0 11 01 39 03 01 00 40
2018-11-28 10:28:31.959 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.1' to '7/1/3'
2018-11-28 10:28:31.959 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.1->7/1/3 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:31.961 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Write telegram from '1.1.1' for destination '7/1/3'
2018-11-28 10:28:31.964 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' processes a Group Write telegram for destination '7/1/3' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B1:Ch_B1_C'
2018-11-28 10:28:31.966 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:34.902 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/3 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:34.932 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/3: no confirmation reply received for 1.2.200->7/1/3 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:34.985 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/2/9
2018-11-28 10:28:34.987 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/2/9 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:34.990 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 163, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a3 00 11 00 bc e0 12 c8 3a 09 01 00 00
2018-11-28 10:28:34.996 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 163 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:34.999 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 30 (channel 9) cEMI 29 00 bc e0 12 c8 3a 09 01 00 00
2018-11-28 10:28:35.002 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/2/9 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:35.002 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/2/9'
2018-11-28 10:28:35.005 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' received a Group Read Request telegram from '1.2.200' for destination '7/2/9'
2018-11-28 10:28:35.063 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 31 (channel 9) cEMI 29 00 bc e0 11 03 3a 09 01 00 40
2018-11-28 10:28:35.064 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.3' to '7/2/9'
2018-11-28 10:28:35.064 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.3->7/2/9 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:35.067 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' received a Group Write telegram from '1.1.3' for destination '7/2/9'
2018-11-28 10:28:35.071 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B4' processes a Group Write telegram for destination '7/2/9' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B4:Ch_B4_I'
2018-11-28 10:28:35.074 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:35.391 [TRACE] [.internal.handler.DeviceThingHandler] - Handling command 'ON' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:35.416 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2018-11-28 10:28:38.005 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/2/9 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:38.054 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/2/9: no confirmation reply received for 1.2.200->7/2/9 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:38.055 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 164, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a4 00 11 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:28:38.063 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 164 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:38.066 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 32 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:28:38.070 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:28:38.077 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:28:38.080 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:28:38.085 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:38.088 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:38.108 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/24
2018-11-28 10:28:38.111 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/24 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:38.299 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 33 (channel 9) cEMI 29 00 bc e0 11 04 3a 15 01 00 81
2018-11-28 10:28:38.301 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.4->7/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:28:38.301 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.1.4' to '7/2/21'
2018-11-28 10:28:38.307 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.1.4' for destination '7/2/21'
2018-11-28 10:28:38.309 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '7/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:38.311 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:41.063 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:41.073 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 165, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a5 00 11 00 bc e0 12 c8 39 18 01 00 00
2018-11-28 10:28:41.073 [DEBUG] [nx.internal.client.AbstractKNXClient] - Value 'ON' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81. Will retry.
2018-11-28 10:28:41.076 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2018-11-28 10:28:41.079 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 165 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:41.082 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 34 (channel 9) cEMI 29 00 bc e0 12 c8 39 18 01 00 00
2018-11-28 10:28:41.085 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/24'
2018-11-28 10:28:41.088 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/24 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:41.088 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Read Request telegram from '1.2.200' for destination '7/1/24'
2018-11-28 10:28:41.136 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 35 (channel 9) cEMI 29 00 bc e0 11 35 39 18 01 00 40
2018-11-28 10:28:41.140 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.53->7/1/24 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:41.140 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.53' to '7/1/24'
2018-11-28 10:28:41.142 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Write telegram from '1.1.53' for destination '7/1/24'
2018-11-28 10:28:41.148 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' processes a Group Write telegram for destination '7/1/24' for channel 'knx:device:WEINZIERL771:MDT_AKS_0816_B2:Ch_B2_D'
2018-11-28 10:28:41.152 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:44.080 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/24 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:44.133 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/24: no confirmation reply received for 1.2.200->7/1/24 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:44.133 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 166, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a6 00 11 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:28:44.142 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 166 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:44.146 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 36 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:28:44.149 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:28:44.149 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:28:44.153 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:28:44.157 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:44.163 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:44.187 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/4
2018-11-28 10:28:44.188 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/4 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:47.145 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:47.156 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'ON' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81. Giving up now.
2018-11-28 10:28:47.158 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 167, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a7 00 11 00 bc e0 12 c8 39 04 01 00 00
2018-11-28 10:28:47.167 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 167 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:47.164 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:47.175 [TRACE] [.internal.handler.DeviceThingHandler] - Handling command 'OFF' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:47.177 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 37 (channel 9) cEMI 29 00 bc e0 12 c8 39 04 01 00 00
2018-11-28 10:28:47.179 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/4 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:47.179 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/4'
2018-11-28 10:28:47.181 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
2018-11-28 10:28:47.183 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Read Request telegram from '1.2.200' for destination '7/1/4'
2018-11-28 10:28:47.233 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 38 (channel 9) cEMI 29 00 bc e0 11 01 39 04 01 00 40
2018-11-28 10:28:47.237 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.1' to '7/1/4'
2018-11-28 10:28:47.237 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.1->7/1/4 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:47.240 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Write telegram from '1.1.1' for destination '7/1/4'
2018-11-28 10:28:47.244 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' processes a Group Write telegram for destination '7/1/4' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B1:Ch_B1_D'
2018-11-28 10:28:47.247 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001

:

[aviperi]

The openhab.logs during the test when the light turn On->OFF->ON (Part II)

2018-11-28 10:28:50.167 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/4 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:50.220 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 168, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a8 00 11 00 bc e0 12 c8 02 15 01 00 80
2018-11-28 10:28:50.223 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/4: no confirmation reply received for 1.2.200->7/1/4 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:50.226 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 168 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:50.231 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 39 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 80
2018-11-28 10:28:50.236 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 80
2018-11-28 10:28:50.236 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:28:50.239 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:28:50.242 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:50.244 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:50.277 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/25
2018-11-28 10:28:50.279 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/25 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:50.397 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 40 (channel 9) cEMI 29 00 bc e0 11 04 3a 15 01 00 80
2018-11-28 10:28:50.399 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.1.4' to '7/2/21'
2018-11-28 10:28:50.399 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.4->7/2/21 L_Data.ind, low priority hop count 6, tpdu 00 80
2018-11-28 10:28:50.401 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.1.4' for destination '7/2/21'
2018-11-28 10:28:50.403 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '7/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:50.404 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:53.227 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:53.235 [DEBUG] [nx.internal.client.AbstractKNXClient] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80. Will retry.
2018-11-28 10:28:53.237 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
2018-11-28 10:28:53.240 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 169, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 a9 00 11 00 bc e0 12 c8 39 19 01 00 00
2018-11-28 10:28:53.248 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 169 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:53.252 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 41 (channel 9) cEMI 29 00 bc e0 12 c8 39 19 01 00 00
2018-11-28 10:28:53.256 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/25'
2018-11-28 10:28:53.256 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/25 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:53.259 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Read Request telegram from '1.2.200' for destination '7/1/25'
2018-11-28 10:28:53.304 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 42 (channel 9) cEMI 29 00 bc e0 11 35 39 19 01 00 40
2018-11-28 10:28:53.308 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.53->7/1/25 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:53.308 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.53' to '7/1/25'
2018-11-28 10:28:53.312 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' received a Group Write telegram from '1.1.53' for destination '7/1/25'
2018-11-28 10:28:53.317 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_0816_B2' processes a Group Write telegram for destination '7/1/25' for channel 'knx:device:WEINZIERL771:MDT_AKS_0816_B2:Ch_B2_E'
2018-11-28 10:28:53.321 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:56.248 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/25 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:56.359 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/25: no confirmation reply received for 1.2.200->7/1/25 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:28:56.359 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 170, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 aa 00 11 00 bc e0 12 c8 02 15 01 00 80
2018-11-28 10:28:56.364 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 170 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:56.367 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 43 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 80
2018-11-28 10:28:56.368 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:28:56.371 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 80
2018-11-28 10:28:56.371 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:28:56.374 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:56.376 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:28:56.411 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/5
2018-11-28 10:28:56.414 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/5 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:28:59.365 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:59.373 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 0/2/21 'knx:ip:WEINZIERL771', DPT id 1.001, low priority': no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80. Giving up now.
2018-11-28 10:28:59.373 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 171, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 ab 00 11 00 bc e0 12 c8 39 05 01 00 00
2018-11-28 10:28:59.376 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:401) ~[203:org.openhab.binding.knx:2.3.0]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:359) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:444) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:410) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$6(DeviceThingHandler.java:211) ~[203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:121) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:115) [203:org.openhab.binding.knx:2.3.0]
	at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:208) [203:org.openhab.binding.knx:2.3.0]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at com.sun.proxy.$Proxy129.handleCommand(Unknown Source) [203:org.openhab.binding.knx:2.3.0]
	at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:75) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:49) [108:org.eclipse.smarthome.core.thing:0.10.0.oh230]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
	at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [101:org.eclipse.smarthome.core:0.10.0.oh230]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:28:59.386 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 171 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:28:59.386 [TRACE] [.internal.handler.DeviceThingHandler] - Handling command 'ON' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:28:59.389 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 44 (channel 9) cEMI 29 00 bc e0 12 c8 39 05 01 00 00
2018-11-28 10:28:59.390 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->0/2/21 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2018-11-28 10:28:59.402 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Request telegram from '1.2.200' to '7/1/5'
2018-11-28 10:28:59.402 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->7/1/5 L_Data.ind, low priority hop count 6, tpdu 00 00
2018-11-28 10:28:59.406 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Read Request telegram from '1.2.200' for destination '7/1/5'
2018-11-28 10:28:59.451 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 45 (channel 9) cEMI 29 00 bc e0 11 01 39 05 01 00 40
2018-11-28 10:28:59.454 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.1' to '7/1/5'
2018-11-28 10:28:59.454 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.1->7/1/5 L_Data.ind, low priority hop count 6, tpdu 00 40
2018-11-28 10:28:59.457 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' received a Group Write telegram from '1.1.1' for destination '7/1/5'
2018-11-28 10:28:59.462 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B1' processes a Group Write telegram for destination '7/1/5' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B1:Ch_B1_E'
2018-11-28 10:28:59.465 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:29:02.392 [WARN ] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 1.2.200->7/1/5 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
	at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[?:?]
	at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[?:?]
	at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:178) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:243) ~[?:?]
	at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:351) ~[?:?]
	at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:222) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.readFromGroup(ProcessCommunicatorImpl.java:418) ~[?:?]
	at tuwien.auto.calimero.process.ProcessCommunicatorImpl.read(ProcessCommunicatorImpl.java:346) ~[?:?]
	at org.openhab.binding.knx.internal.client.AbstractKNXClient.readNextQueuedDatapoint(AbstractKNXClient.java:284) ~[?:?]
	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:1142) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [?:?]
	at java.lang.Thread.run(Thread.java:745) [?:?]
2018-11-28 10:29:02.442 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 7/1/5: no confirmation reply received for 1.2.200->7/1/5 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.
2018-11-28 10:29:02.442 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - sending cEMI frame seq 172, WaitForCon, attempt 1 (channel 9) 06 10 04 20 00 15 04 09 ac 00 11 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:29:02.448 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received service ack 172 from /10.0.0.24:3671 (channel 9)
2018-11-28 10:29:02.451 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 46 (channel 9) cEMI 29 00 bc e0 12 c8 02 15 01 00 81
2018-11-28 10:29:02.453 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.2.200->0/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:29:02.453 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.2.200' to '0/2/21'
2018-11-28 10:29:02.457 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.2.200' for destination '0/2/21'
2018-11-28 10:29:02.461 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '0/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:29:02.465 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001
2018-11-28 10:29:02.495 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 7/1/27
2018-11-28 10:29:02.497 [DEBUG] [calimero.link.10.0.0.24:3671        ] - send (wait for confirmation) 1.2.200->7/1/27 L_Data.req, low priority hop count 6 repeat, tpdu 00 00
2018-11-28 10:29:02.672 [TRACE] [p.KNXnet/IP Tunneling 10.0.0.24:3671] - received request seq 47 (channel 9) cEMI 29 00 bc e0 11 04 3a 15 01 00 81
2018-11-28 10:29:02.675 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.1.4' to '7/2/21'
2018-11-28 10:29:02.675 [DEBUG] [calimero.link.10.0.0.24:3671        ] - indication 1.1.4->7/2/21 L_Data.ind, low priority hop count 6, tpdu 00 81
2018-11-28 10:29:02.677 [DEBUG] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' received a Group Write telegram from '1.1.4' for destination '7/2/21'
2018-11-28 10:29:02.681 [TRACE] [.internal.handler.DeviceThingHandler] - Thing 'knx:device:WEINZIERL771:MDT_AKS_2016_B5' processes a Group Write telegram for destination '7/2/21' for channel 'knx:device:WEINZIERL771:MDT_AKS_2016_B5:Ch_B5_A'
2018-11-28 10:29:02.685 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001

[aviperi]

Does anyone see a clue for the delay problem?
Thanks

[aviperi]

Am I the only one who face it?

[oliver_kuhl (Ollie)]

@aviperi, I have the same problem too for a couple of weeks. At first, I thought it could have something to do with the virtual machine that I run openHAB on my Synology NAS. After I found your post here I think it’s a different problem, So may be the same as yours.
Do you have any news from your side? Any solution?

[David_Graeff]

Looks like a knx telegram problem. Other knx devices work without a lag?

[aviperi]

I’m still having the problem. When using the wall switch there is no problem only when using openHAB. I don’t have any clue why it behaves like that. I would appreciate if someone can assist.
Thanks

[Scylla (Haka Keller)]

Hi,
I have an identical problem and was able to narrow it down a bit.
Some facts on my environment first:

• my IP Gateway is a Weinzierl IP 730 (Tunnel) Providing 5 Tunnels
• The Tunnels KNX Addresses reach from 15.15.250 - 15.15.254
• in KNX.things, the address is set to 15.15.250
• there are at least 2 separate installations using the IP Gateway, sometimes 3 (Debug-Machine) or even 4 (ETS)
  • 1. OpenHab 2
  • 2. OpenHab 1.8.3 (intended as fallback as long as OH2.0 has not prooven full stability in my setup)
  • Test / Debug Instance
  • ETS Machine
• all devices in this setup are having the same IP Address being provided via DHCP each time

What I observed so far:

Scenario 1: Full restart of all machines, like from a power outage

• When the OH2.0 Machine is the first to be up and running, claiming the first Tunnel on the IP Gateway (thus having the LocalAddress matched to the one it has gotten provided from the Gateway), everything works perfectly.
• When the OH 1.8.3 is faster (which happens sometimes), I get KNX Errors similar to yours from the very beginnning

Scenario 2: Enforce an improper address matching

• OH2 Machine works smoothly (i.e. Address is 15.15.250, observed via the ETS)
• Have OH2 drop the knx tunnel connection (shutdown OH or disconnect the network cable - my preferred way whilst having a stationery screen attached to still observe the logs)
• Wait some minutes to have the Weinzierl free up the 1st tunnel, then boot up the debug machine so it will claim the 1st tunnel
• re-connect the network cable of the OH2 machine and watch the logs going wild

Scenario 3: Not having the local address set / leave it to 0.0.0

• this caused the same symptoms you described, i.e. lags of multiple seconds until the command was issued on the bus

Side Note - Berserk Mode on the Bus
On each repetition of scenario 1 and 2, I recognized that the OH2 machine went fully retard / berserk mode on the bus - e.g.:

• When switching by a regular classic KNX wall switch, it repeated the message in reverse with a 1-5 seconds delay - no chance to switch anything permanentely on or of but by shutting down OH2
• Even worse with motion sensors being attached to the bus (they also react on lights being switched on) - OH2 created a perpetuum mobile in my hallways strangling with my motion sensors.

Bottom Line
I never observed these issues with KNX 1.8.3 and would love to restrain myself from buying an OH2 exclusive IP Gateway, therefore OH2 is not an option for me until these issues are fixed

Best
Hans

[Drizzt81 (Greg Kronenberger)]

I am quite interested in any updates on this.
I run a Weinzierl BAOS 770 as well and get similar issues as the initial poster. Updating the LocalAddress in the configuration to the actual Weizierl Adress did not improve the issue - unfortunately.

Running 2.4.0