search

calimero-project / calimero-core

Core library for KNX network access and management
Other
130 stars 64 forks source link

maximum send attempts, no service acknowledgment received #88

Closed lewie closed 3 years ago

lewie commented 5 years ago

@bmalinowsky, do you have any idea about that: https://github.com/openhab/openhab2-addons/issues/5861#issue-472566348

Thank you for your help in advance...

PBrou commented 5 years ago

Suffering from this issue on raspberry Pi3+, if you need some testing, please let me know. Kr PBrou

bmalinowsky commented 5 years ago

@PBrou does a confirmation even show on the network, i.e., is it sent by your router? If not, there is nothing much to do other than to close the connection. If a confirmation was sent, then it could indicate a protocol problem. (If your router supports telnet, you could check if there is further information.)

PBrou commented 5 years ago

@bmalinowsky , It is not clear for me if there is a correlation between the large set of "no confirmation reply received" KNX telegrams piling up and the eventually crashing/stopping/disconnect with the KNX bus. I checked my KNX bus and I did find out that for an alarm event on a movement sensor with 1-bit object and also a new CO2/Humidity/temp sensor with 2-byte value objects there is/was in fact no receive confirmation as there is only this single object in the KNX group. At some moment I saw also a lot of LL-BUSY on my telegrams. Due to this (only one item in KNX group) these KNX sensors are/were constantly resending (2 extra times) which as such is normal KNX behavior but slightly overloading needlessly my KNX bus. For the movement sensor event I fixed it by just connecting it into a non-used input of an actor, but for the 2-byte value I don't know yet how to do this. For now I think I'll block the sending out of the values on change and the cyclic sending, rather using a strategy or cron rule in openhab.

Concerning your question, yes the KNX-bus does show the confirmation but openhab tries to send a second time (though not sure why it shows diagnostics shows 15.15.255 as originator while my ip gateway is on 1.1.100 and openhab was previously not on 15.15.255...) image And is gives this warning: 2019-09-08 16:30:18.989 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->7/2/10 L_Data.req, low priority hop count 6 repeat, tpdu 00 80 at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:com.github.calimero.calimero-core:2.4.0] .... 2019-09-08 16:30:22.002 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->7/2/10 L_Data.req, low priority hop count 6 repeat, tpdu 00 80 at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[203:com.github.calimero.calimero-core:2.4.0] ... 2019-09-08 16:30:22.031 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 7/2/10 'knx:ip:2a706897', DPT id 1.001, low priority': no confirmation reply received for 15.15.255->7/2/10 L_Data.req, low priority hop count 6 repeat, tpdu 00 80. Giving up now. 2019-09-08 16:30:22.034 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:a3655fba:WaterFillValve: no confirmation reply received for 15.15.255->7/2/10 L_Data.req, low priority hop count 6 repeat, tpdu 00 80 tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->7/2/10 L_Data.req, low priority hop count 6 repeat, tpdu 00 80 ... So it looks like openhab does not see the ACK and therefore tries again??? The KNX connection - for now - keeps running. The first error arrived 3 hours after reboot. Then it was ok again, it then reappeared after another 13 hours, and also 1h20 later again...?

@lewie , I have here a question for openhab2.x - sorry for hijacking this thread for this - is there a way that openhab can act as consumer (like an actor KNX device) of such value broadcast group telegram and provide the receive confirmation?

I hope this make some sense.. I am using the - inferior (but cheaper) GIRA IP Interface.. (not the router) and thus using tunnel mode. With OH2.4 (and before the new CO2/Hum/Temp sensor) previously on Mac mini (before migration to Pi3B+ my KNX connection was super stable. I'll continue to do some tests, removing some elements to narrow down the problem.

bmalinowsky commented 5 years ago

(15.15.255 is usually not used as a default, whether in calimero or knx.)

There is a correlation between .con and closing the connection wrt that a .con is required by the protocol (so the server has to send it). Calimero won't close the connection based on that, but it's an indicator that something ran afoul.

The missing ack based on which calimero closes the connection, is the acknowledge of a tunneled frame by the server, and solely related to the tunneling protocol (not to any ack on the knx bus).

From what you describe I currently would suspect a timing issue, which also became observable over the tunneling connection.

If you can deterministically reproduce the behavior, you can check for the (missing) confirmation over IP using wireshark (type "knx" in the display filter). This would clarify whether the confirmation is lost due to timing (too late), or not sent at all.

PBrou commented 5 years ago

I finally have my knx bus traffic logging + wireshark + port mirroring on my switch. In this very first analysis I don't think there are real issues on the KNX IP traffic between my Pi3B+ and the IP Gateway itself. However I do see some (strange) double requests sometimes. Openhab (2.5.0 Build 1711) seems to trigger much too soon a second try on some KNX group read!? KNX-TunnelAck-20191005-165411 It also looks like there is a tunnel check connection done every 1s - probably cannot harm? KNX-TunnelAck-DoubleReadRequests-20191005-165512 I will do some more testing with KNX Bus logging + Calimero debug level in openhab + wireshark.

bmalinowsky commented 5 years ago

The repetition after 1 second is required by the protocol (and 1 second in a LAN is a long time to wait for an ACK). You can see the "normal" timing if your KNX server answers it does it quite quickly, there is a factor 10^3 difference. Another strange thing is that the server ignores a request, but then sends a .con twice, even though the first gets immediately ACKed by the client. Not normal behavior.

Regarding tunnel check connection: you mean the connection-state request? That's done every minute, not second.

PBrou commented 4 years ago

Please find some more test results from a few weeks ago. In my case it looks like sometimes there are one or two KNX request without an ACK on the bus. I have the impression that the software kind of looses control/track of the situation after such situation ( some error stack not cleaned, some error situation that stays pending somewhere ) and doesn't recover back fast to a 'normal' situation... The two requests without ACK lead to a situation with mixed, interweaving of two parallel retries..

View from the KNX BUS

All normal first.. the last 10/1/0 is working fine 21:52:47.084 S=0 L 1.1.19 Keuken - 2/1/0 Keukeneiland 6 Write 1 bit $00 LL-ACK 21:52:47.194 S=2 A 1.1.3 Lichten. 2/3/0 Status Keuken 6 Write 1 bit $00 LL-ACK21:53:18.970 S=4 L 15.15.255 Openhab Server 10/1/0 Vochtigheid Badkamer 6 Read - LL-ACK 21:53:37.317 S=6 L 1.1.39 Sensor Vochtigheid, Temp, CO2 10/1/0 Vochtigheid Badkamer 6 Response 2 byte 15 36 | 53,36 LL-ACK

The following read does not show an ACK on the bus (?) - the 10/0/0 > no ACK 21:54:17.314 S=0 L 15.15.255 Openhab Server 10/0/0 Temperatuur Badkamer 6 Read - We'll see retries for this in the openhab log file. Meanwhile a 2nd read is launch (while the other is still retrying) This one also on the bus without ACK 21:54:57.312 S=4 L 15.15.255 Openhab Server 10/2/0 CO2 Badkamer 6 Read - Then back to normal (just status messages) 21:55:26.574 S=0 L 1.1.2 Rolluiken Garage; Sturing Verwarming; Lichten Toilet+Verluchting+Lichten buiten. 2/3/9 Status Licht Toilet Boven 6 Write 1 bit $00 21:55:26.584 S=2 L 1.1.3 Lichten. 2/3/2 Status Wasplaats Licht 1 6 Write 1 bit $00

And then back too with a normal read situation with ACK on the bus 21:58:19.072 S=4 L 15.15.255 Openhab Server 10/1/0 Vochtigheid Badkamer 6 Read - LL-ACK 21:58:19.102 S=6 L 1.1.39 Sensor Vochtigheid, Temp, CO2 10/1/0 Vochtigheid Badkamer 6 Response 2 byte 15 34 | 53,28 LL-ACK

And now a 10/0/0 back normal with an ACK 21:58:22.346 S=0 L 15.15.255 Openhab Server 10/0/0 Temperatuur Badkamer 6 Read - LL-ACK 21:58:22.386 S=2 L 1.1.39 Sensor Vochtigheid, Temp, CO2 10/0/0 Temperatuur Badkamer 6 Response 2 byte 0C 88 | 23,2 LL-ACK 21:58:25.641 S=4 L 15.15.255 Openhab Server 10/2/0 CO2 Badkamer 6 Read - LL-ACK 21:58:25.671 S=6 L 1.1.39 Sensor Vochtigheid, Temp, CO2 10/2/0 CO2 Badkamer 6 Response 2 byte 2E D6 | 560 LL-ACK

View on the KNX IP traffic (PI <-> IP Interface tunnel mode)

Line 4420+4430: there seems to be a double response value on the IP KNX level - normal? Line 4423, 4432,4539,.: the multiple retries on the 10/0/0 groupRead request

image

View in openhab log file with calimero tracing on

2019-10-08 21:52:47.163 [TRACE] [.internal.handler.DeviceThingHandler] - onGroupWrite Thing 'knx:device:b063da47' processes a GroupValueWrite telegram for destination '2/1/0' for channel 'knx:device:b063da47:Light_GF_Kitchen_TL' 2019-10-08 21:52:47.169 [TRACE] [.internal.handler.DeviceThingHandler] - onGroupWrite isControl 2019-10-08 21:52:47.177 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001 2019-10-08 21:52:47.183 [TRACE] [.knx.internal.channel.KNXChannelType] - getCommandSpec testing Keys '[ga]' for command 'OFF' 2019-10-08 21:52:47.192 [TRACE] [.knx.internal.channel.KNXChannelType] - getCommandSpec key 'ga' uses expectedTypeClass 'class org.eclipse.smarthome.core.library.types.OnOffType' witch isInstance for command 'OFF' and dpt '1.001' 2019-10-08 21:52:47.201 [TRACE] [.internal.handler.DeviceThingHandler] - rememberRespondingSpec handled commandSpec for '2/1/0' size '1' added 'true' 2019-10-08 21:52:47.208 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 1.001 2019-10-08 21:52:47.215 [TRACE] [.internal.handler.DeviceThingHandler] - processDataReceived postCommand new value '[0]' for GA 'null' 2019-10-08 21:52:47.233 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received request seq 35 (channel 67) cEMI 29 00 b8 e0 11 03 13 00 01 00 80 2019-10-08 21:52:47.241 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Write telegram from '1.1.3' to '2/3/0' with value '[0]' 2019-10-08 21:52:47.241 [DEBUG] [calimero.link.192.168.1.249:3671 ] - indication 1.1.3->2/3/0 L_Data.ind, urgent priority hop count 6, tpdu 00 80 2019-10-08 21:52:48.943 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:53:18.962 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/1/0 2019-10-08 21:53:18.972 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/1/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:18.981 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 9, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 09 00 11 00 bc e0 ff ff 51 00 01 00 00 2019-10-08 21:53:18.988 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 9 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:19.032 [DEBUG] [Xnet/IP Tunneling 192.168.1.249:3671] - received request seq 36 (channel 67) cEMI L-Data.con 15.15.255->10/1/0 2019-10-08 21:53:19.041 [DEBUG] [calimero.link.192.168.1.249:3671 ] - confirmation of 10/1/0 2019-10-08 21:53:19.046 [TRACE] [calimero.link.192.168.1.249:3671 ] - send 15.15.255->10/1/0 succeeded 2019-10-08 21:53:19.052 [TRACE] [ess.communication 192.168.1.249:3671] - sent group read request to 10/1/0 2019-10-08 21:53:19.082 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received request seq 37 (channel 67) cEMI 29 00 bc e0 11 27 51 00 03 00 40 15 36 2019-10-08 21:53:19.088 [DEBUG] [calimero.link.192.168.1.249:3671 ] - indication 1.1.39->10/1/0 L_Data.ind, low priority hop count 6, tpdu 00 40 15 36 2019-10-08 21:53:19.090 [TRACE] [nx.internal.client.AbstractKNXClient] - Received a Group Read Response telegram from '1.1.39' to '10/1/0' with value '[21, 54]' 2019-10-08 21:53:19.106 [TRACE] [.internal.handler.DeviceThingHandler] - onGroupReadResponse Thing 'knx:device:dbb9892a' processes a GroupValueResponse telegram for destination '10/1/0' 2019-10-08 21:53:19.124 [DEBUG] [.internal.handler.DeviceThingHandler] - onGroupWrite Thing 'knx:device:dbb9892a' received a GroupValueWrite telegram from '1.1.39' for destination '10/1/0' 2019-10-08 21:53:19.136 [TRACE] [.internal.handler.DeviceThingHandler] - onGroupWrite Thing 'knx:device:dbb9892a' processes a GroupValueWrite telegram for destination '10/1/0' for channel 'knx:device:dbb9892a:SensorBathroomHumidity' 2019-10-08 21:53:19.148 [TRACE] [g.knx.internal.dpt.KNXCoreTypeMapper] - toType datapoint DPT = 9.001 2019-10-08 21:53:19.290 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/0/0 2019-10-08 21:53:19.295 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:19.300 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 10, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0a 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:19.306 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 10 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:20.082 [DEBUG] [Xnet/IP Tunneling 192.168.1.249:3671] - skip tunneling request with rcv-seq 37 (already received) 2019-10-08 21:53:20.089 [DEBUG] [Xnet/IP Tunneling 192.168.1.249:3671] - received request seq 38 (channel 67) cEMI L-Data.con 15.15.255->10/0/0 2019-10-08 21:53:20.094 [DEBUG] [calimero.link.192.168.1.249:3671 ] - confirmation of 10/0/0 2019-10-08 21:53:20.103 [TRACE] [calimero.link.192.168.1.249:3671 ] - send 15.15.255->10/0/0 succeeded 2019-10-08 21:53:20.113 [TRACE] [ess.communication 192.168.1.249:3671] - sent group read request to 10/0/0 2019-10-08 21:53:21.083 [DEBUG] [Xnet/IP Tunneling 192.168.1.249:3671] - skip tunneling request with rcv-seq 38 (already received) 2019-10-08 21:53:30.123 [INFO ] [ess.communication 192.168.1.249:3671] - timeout waiting for group read response from 10/0/0 2019-10-08 21:53:30.137 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/0/0: timeout waiting for group read response from 10/0/0. Going to retry. 2019-10-08 21:53:30.343 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/2/0 2019-10-08 21:53:30.351 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:30.360 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 11, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0b 00 11 00 bc e0 ff ff 52 00 01 00 00 2019-10-08 21:53:30.369 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 11 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:33.370 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:33.436 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/2/0: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:33.642 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/0/0 2019-10-08 21:53:33.645 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:33.649 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 12, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0c 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:33.653 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 12 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:36.654 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:36.702 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/0/0: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:36.907 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/2/0 2019-10-08 21:53:36.910 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:36.914 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 13, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0d 00 11 00 bc e0 ff ff 52 00 01 00 00 2019-10-08 21:53:36.918 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 13 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:39.919 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:39.969 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/2/0: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:40.175 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/0/0 2019-10-08 21:53:40.179 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:40.182 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 14, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0e 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:41.187 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 14, WaitForCon, attempt 2 (channel 67) 06 10 04 20 00 15 04 43 0e 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:41.197 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 14 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:44.197 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:44.225 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/0/0: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:44.429 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/2/0 2019-10-08 21:53:44.433 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:44.438 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 15, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 0f 00 11 00 bc e0 ff ff 52 00 01 00 00 2019-10-08 21:53:44.443 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 15 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:47.443 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:47.508 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/2/0: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:47.713 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/0/0 2019-10-08 21:53:47.717 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:47.721 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 16, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 10 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:47.725 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 16 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:48.953 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:53:50.725 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:50.771 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/0/0: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:50.977 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/2/0 2019-10-08 21:53:50.981 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:50.985 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 17, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 11 00 11 00 bc e0 ff ff 52 00 01 00 00 2019-10-08 21:53:50.991 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 17 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:53.993 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:54.039 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/2/0: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry. 2019-10-08 21:53:54.253 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/0/0 2019-10-08 21:53:54.256 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:54.261 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 18, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 12 00 11 00 bc e0 ff ff 50 00 01 00 00 2019-10-08 21:53:54.266 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 18 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:53:57.266 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/0/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:53:57.314 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 10/0/0, the number of maximum retries (5) is reached. 2019-10-08 21:53:57.523 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/2/0 2019-10-08 21:53:57.533 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:53:57.539 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 19, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 13 00 11 00 bc e0 ff ff 52 00 01 00 00 2019-10-08 21:53:57.550 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 19 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:54:00.550 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/2/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:54:00.611 [WARN ] [nx.internal.client.AbstractKNXClient] - Giving up reading datapoint 10/2/0, the number of maximum retries (5) is reached. 2019-10-08 21:54:48.960 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:55:48.970 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:56:48.979 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:57:18.386 [INFO ] [se.smarthome.model.script.home.rules] - Month=10 2019-10-08 21:57:18.414 [INFO ] [se.smarthome.model.script.home.rules] - Maximum Elevation this month=20 2019-10-08 21:57:18.422 [INFO ] [se.smarthome.model.script.home.rules] - Elevation state=-26.553889786176605 ° 2019-10-08 21:57:18.432 [INFO ] [se.smarthome.model.script.home.rules] - Elevation value=-26.553889786176605 ° 2019-10-08 21:57:18.442 [INFO ] [se.smarthome.model.script.home.rules] - Daylight state=OFF 2019-10-08 21:57:18.457 [INFO ] [.smarthome.model.script.houseControl] - Sun angle under -3 degrees 2019-10-08 21:57:18.479 [INFO ] [se.smarthome.model.script.home.rules] - Elevation state=20.0 °

Here I would expect (based upon BUS view and IP KNX view) things to be normal again, but this is not the case ! 2019-10-08 21:57:48.991 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending connection state request, attempt 1 2019-10-08 21:58:19.074 [TRACE] [nx.internal.client.AbstractKNXClient] - Sending a Group Read Request telegram for 10/1/0 2019-10-08 21:58:19.084 [DEBUG] [calimero.link.192.168.1.249:3671 ] - send (wait for confirmation) 15.15.255->10/1/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00 2019-10-08 21:58:19.093 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - sending cEMI frame seq 20, WaitForCon, attempt 1 (channel 67) 06 10 04 20 00 15 04 43 14 00 11 00 bc e0 ff ff 51 00 01 00 00 2019-10-08 21:58:19.103 [TRACE] [Xnet/IP Tunneling 192.168.1.249:3671] - received service ack 20 from /192.168.1.249:3671 (channel 67) 2019-10-08 21:58:22.103 [WARN ] [Xnet/IP Tunneling 192.168.1.249:3671] - response timeout waiting for confirmation tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 15.15.255->10/1/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00

2019-10-08 21:58:22.161 [DEBUG] [nx.internal.client.AbstractKNXClient] - Could not read value for datapoint 10/1/0: no confirmation reply received for 15.15.255->10/1/0 L_Data.req, low priority hop count 6 repeat, tpdu 00 00. Going to retry.

petero-dk commented 4 years ago

@PBrou I am also a KNX in openHAB user (although I am going the serial device route and not tcp/ip) I thought I would just let you know about two things:

  1. When you paste log files in github issues they are much easier to read if you enclose them in code tags ``` (blank line, code tags, log content, code tags, blank line) then it will look like this
this can be a really long log line, but it will not wrap, never, not ever, never ever ever ever ever ever ever ever ever ever ever wrap. No never, not ever. Still wont.
  1. The calimero version used in the knx binding is actually quite old (comparativly speaking, in calendar time it is not, but @bmalinowsky is doing a lot of work :-)). It is fixed at version calimero 2.4 because that was the last version to support Java 8. So none of the latest developments in calimero is reaching openHAB until (probably) openHAB 3
petero-dk commented 4 years ago

This is the very latest knx binding for openHAB with the very latest calimaro source (back compiled to java8). I do not know if it will make a difference for you.

org.openhab.binding.knx-2.5.0-SNAPSHOT.jar.zip

villaRob commented 3 years ago

Hi all, any news on this ? I'm facing the same problem also with the stable openHAB 3 and latest KNX binding.

I'm available for testing or if further information is needed.

Basically, the issue is the same I had with OH2 (reason that block me to leave openhab 1.8.3 as my working enviroment)

This is an extract of openhab log:

2021-01-07 18:33:14.580 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/8 L_Data.ind, low priority hop count 6, tpdu 00 80 00 2e
2021-01-07 18:33:14.610 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 115 (channel 5) cEMI 29 00 bc e0 01 19 02 09 03 00 80 00 12
2021-01-07 18:33:14.611 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/9 L_Data.ind, low priority hop count 6, tpdu 00 80 00 12
2021-01-07 18:33:14.950 [DEBUG] [calimero.link.192.168.7.107:3671    ] - send (wait for confirmation) 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
2021-01-07 18:33:14.951 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - sending cEMI frame seq 3, WaitForCon, attempt 1 (channel 5) 06 10 04 20 00 15 04 05 03 00 11 00 bc e0 01 f2 31 01 01 00 80
2021-01-07 18:33:14.955 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received service ack 3 from /192.168.7.107:3671 (channel 5)
2021-01-07 18:33:14.959 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 116 (channel 5) cEMI 29 00 bc e0 01 f2 31 01 01 00 80
2021-01-07 18:33:14.959 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.242->6/1/1 L_Data.ind, low priority hop count 6, tpdu 00 80
2021-01-07 18:33:15.114 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 117 (channel 5) cEMI 29 00 bc e0 01 3b 31 02 01 00 80
2021-01-07 18:33:15.115 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.59->6/1/2 L_Data.ind, low priority hop count 6, tpdu 00 80
2021-01-07 18:33:17.103 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 118 (channel 5) cEMI 29 00 bc e0 01 42 32 0e 05 00 80 3f 8e 14 7b
2021-01-07 18:33:17.104 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.66->6/2/14 L_Data.ind, low priority hop count 6, tpdu 00 80 3f 8e 14 7b
2021-01-07 18:33:17.958 [WARN ] [Xnet/IP Tunneling 192.168.7.107:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) [bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy165.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:18.059 [DEBUG] [calimero.link.192.168.7.107:3671    ] - send (wait for confirmation) 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
2021-01-07 18:33:18.062 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - sending cEMI frame seq 4, WaitForCon, attempt 1 (channel 5) 06 10 04 20 00 15 04 05 04 00 11 00 bc e0 01 f2 31 01 01 00 80
2021-01-07 18:33:18.069 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received service ack 4 from /192.168.7.107:3671 (channel 5)
2021-01-07 18:33:18.073 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 119 (channel 5) cEMI 29 00 bc e0 01 f2 31 01 01 00 80
2021-01-07 18:33:18.076 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.242->6/1/1 L_Data.ind, low priority hop count 6, tpdu 00 80
2021-01-07 18:33:18.178 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 120 (channel 5) cEMI 29 00 bc e0 01 26 2b 01 03 00 80 19 07
2021-01-07 18:33:18.182 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.38->5/3/1 L_Data.ind, low priority hop count 6, tpdu 00 80 19 07
2021-01-07 18:33:19.552 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 121 (channel 5) cEMI 29 00 bc e0 01 19 02 07 03 00 80 00 47
2021-01-07 18:33:19.555 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/7 L_Data.ind, low priority hop count 6, tpdu 00 80 00 47
2021-01-07 18:33:19.576 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 122 (channel 5) cEMI 29 00 bc e0 01 19 02 08 03 00 80 00 2e
2021-01-07 18:33:19.580 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/8 L_Data.ind, low priority hop count 6, tpdu 00 80 00 2e
2021-01-07 18:33:19.606 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 123 (channel 5) cEMI 29 00 bc e0 01 19 02 09 03 00 80 00 12
2021-01-07 18:33:19.609 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/9 L_Data.ind, low priority hop count 6, tpdu 00 80 00 12
2021-01-07 18:33:21.070 [WARN ] [Xnet/IP Tunneling 192.168.7.107:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) [bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy165.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:21.102 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 124 (channel 5) cEMI 29 00 bc e0 01 42 32 0e 05 00 80 3f 8a 3d 71
2021-01-07 18:33:21.164 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 6/1/1 'knx:ip:bridge', DPT id 1.001, low priority': no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80. Giving up now.
2021-01-07 18:33:21.167 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.66->6/2/14 L_Data.ind, low priority hop count 6, tpdu 00 80 3f 8a 3d 71
2021-01-07 18:33:21.175 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:bridge:LUCI:Luci_Cameretta_Centrale: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 80
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) ~[bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) ~[bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) ~[bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) ~[bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) ~[bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy165.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:21.274 [DEBUG] [calimero.link.192.168.7.107:3671    ] - send (wait for confirmation) 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2021-01-07 18:33:21.277 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - sending cEMI frame seq 5, WaitForCon, attempt 1 (channel 5) 06 10 04 20 00 15 04 05 05 00 11 00 bc e0 01 f2 31 01 01 00 81
2021-01-07 18:33:21.284 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received service ack 5 from /192.168.7.107:3671 (channel 5)
2021-01-07 18:33:21.287 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 125 (channel 5) cEMI 29 00 bc e0 01 f2 31 01 01 00 81
2021-01-07 18:33:21.291 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.242->6/1/1 L_Data.ind, low priority hop count 6, tpdu 00 81
2021-01-07 18:33:21.434 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 126 (channel 5) cEMI 29 00 bc e0 01 3b 31 02 01 00 81
2021-01-07 18:33:21.437 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.59->6/1/2 L_Data.ind, low priority hop count 6, tpdu 00 81
2021-01-07 18:33:24.283 [WARN ] [Xnet/IP Tunneling 192.168.7.107:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) [bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy166.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:24.370 [DEBUG] [calimero.link.192.168.7.107:3671    ] - send (wait for confirmation) 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
2021-01-07 18:33:24.373 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - sending cEMI frame seq 6, WaitForCon, attempt 1 (channel 5) 06 10 04 20 00 15 04 05 06 00 11 00 bc e0 01 f2 31 01 01 00 81
2021-01-07 18:33:24.380 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received service ack 6 from /192.168.7.107:3671 (channel 5)
2021-01-07 18:33:24.384 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 127 (channel 5) cEMI 29 00 bc e0 01 f2 31 01 01 00 81
2021-01-07 18:33:24.387 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.242->6/1/1 L_Data.ind, low priority hop count 6, tpdu 00 81
2021-01-07 18:33:24.550 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 128 (channel 5) cEMI 29 00 bc e0 01 19 02 07 03 00 80 00 47
2021-01-07 18:33:24.553 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/7 L_Data.ind, low priority hop count 6, tpdu 00 80 00 47
2021-01-07 18:33:24.580 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 129 (channel 5) cEMI 29 00 bc e0 01 19 02 08 03 00 80 00 2e
2021-01-07 18:33:24.584 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/8 L_Data.ind, low priority hop count 6, tpdu 00 80 00 2e
2021-01-07 18:33:24.610 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 130 (channel 5) cEMI 29 00 bc e0 01 19 02 09 03 00 80 00 12
2021-01-07 18:33:24.613 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/9 L_Data.ind, low priority hop count 6, tpdu 00 80 00 12
2021-01-07 18:33:27.380 [WARN ] [Xnet/IP Tunneling 192.168.7.107:3671] - response timeout waiting for confirmation
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) [bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) [bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) [bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) [bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) [bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy166.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:29.551 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 131 (channel 5) cEMI 29 00 bc e0 01 19 02 07 03 00 80 00 47
2021-01-07 18:33:39.227 [WARN ] [nx.internal.client.AbstractKNXClient] - Value 'ON' could not be sent to the KNX bus using datapoint 'command DP 6/1/1 'knx:ip:bridge', DPT id 1.001, low priority': no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81. Giving up now.
2021-01-07 18:33:39.235 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/7 L_Data.ind, low priority hop count 6, tpdu 00 80 00 47
2021-01-07 18:33:39.242 [WARN ] [.internal.handler.DeviceThingHandler] - An error occurred on channel knx:device:bridge:LUCI:Luci_Cameretta_Centrale: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
tuwien.auto.calimero.KNXTimeoutException: no confirmation reply received for 0.1.242->6/1/1 L_Data.req, low priority hop count 6 repeat, tpdu 00 81
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:244) ~[bundleFile:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:258) ~[bundleFile:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:177) ~[bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:264) ~[bundleFile:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:332) ~[bundleFile:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:243) ~[bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:397) ~[bundleFile:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:354) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.sendToKNX(AbstractKNXClient.java:459) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.client.AbstractKNXClient.writeToKNX(AbstractKNXClient.java:419) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.lambda$7(DeviceThingHandler.java:253) ~[bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:148) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.withKNXType(DeviceThingHandler.java:142) [bundleFile:?]
    at org.openhab.binding.knx.internal.handler.DeviceThingHandler.handleCommand(DeviceThingHandler.java:248) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?]
    at com.sun.proxy.$Proxy166.handleCommand(Unknown Source) [?:?]
    at org.openhab.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:80) [bundleFile:?]
    at org.openhab.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
    at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
    at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
    at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
    at org.openhab.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:154) [bundleFile:?]
    at org.openhab.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
    at java.lang.Thread.run(Thread.java:834) [?:?]
2021-01-07 18:33:39.247 [TRACE] [Xnet/IP Tunneling 192.168.7.107:3671] - received request seq 132 (channel 5) cEMI 29 00 bc e0 01 19 02 08 03 00 80 00 2e
2021-01-07 18:33:39.251 [DEBUG] [calimero.link.192.168.7.107:3671    ] - indication 0.1.25->0/2/8 L_Data.ind, low priority hop count 6, tpdu 00 80 00 2e
2021-01-07 18:33:39.259 [DEBUG] [Xnet/IP Tunneling 192.168.7.107:3671] - skip tunneling request with rcv-seq 132 (already received)
2021-01-07 18:33:39.264 [INFO ] [Xnet/IP Tunneling 192.168.7.107:3671] - close connection - server request
2021-01-07 18:33:39.268 [INFO ] [calimero.mgmt.TL 192.168.7.107:3671 ] - attached link was closed
2021-01-07 18:33:39.285 [DEBUG] [calimero.mgmt.TL 192.168.7.107:3671 ] - detached from 192.168.7.107:3671
2021-01-07 18:33:39.356 [DEBUG] [calimero.mgmt.MC 192.168.7.107:3671 ] - detached from 192.168.7.107:3671
2021-01-07 18:33:39.360 [INFO ] [calimero.mgmt.MC 192.168.7.107:3671 ] - attached link was closed
2021-01-07 18:33:39.363 [DEBUG] [calimero.mgmt.TL 192.168.7.107:3671 ] - detached from 192.168.7.107:3671
2021-01-07 18:33:39.366 [INFO ] [calimero.mgmt.TL 192.168.7.107:3671 ] - attached link was closed
2021-01-07 18:33:39.369 [DEBUG] [calimero.mgmt.MC 192.168.7.107:3671 ] - detached from 192.168.7.107:3671
2021-01-07 18:33:39.372 [INFO ] [calimero.mgmt.MC 192.168.7.107:3671 ] - attached link was closed
2021-01-07 18:33:39.379 [INFO ] [ess.communication 192.168.7.107:3671] - detached from link 192.168.7.107:3671
2021-01-07 18:33:39.380 [INFO ] [ess.communication 192.168.7.107:3671] - attached link was closed (server request)
2021-01-07 18:33:39.382 [INFO ] [ice.communication 192.168.7.107:3671] - detached from 192.168.7.107:3671
2021-01-07 18:33:39.386 [INFO ] [calimero.link.192.168.7.107:3671    ] - link closed
2021-01-07 18:33:39.389 [INFO ] [Xnet/IP Tunneling 192.168.7.107:3671] - establish connection from /192.168.7.100:58719 to /192.168.7.107:3671
2021-01-07 18:33:39.396 [DEBUG] [Xnet/IP Tunneling 192.168.7.107:3671] - wait for connect response from /192.168.7.107:3671 ...

This is the channel definition of the ga causing error (the only 2 linked to an item for testing)

Type dimmer                  : Luci_Sala_Lato_Ingresso                     "Lato Ingresso"                              [ switch="1.001:1/1/20+<1/1/26", increaseDecrease="5.001:1/1/22+<1/1/23" ]
Type switch                  : Luci_Cameretta_Centrale                     "Centrale"                                   [ ga="1.001:6/1/1+<6/1/2" ]

and this the bridge config:

Bridge knx:ip:bridge [
    ipAddress="192.168.7.107",
    portNumber=3671,
    localIp="192.168.7.101",
    type="TUNNEL",
    readingPause=50,
    responseTimeout=10,
    readRetriesLimit=3,
    autoReconnectPeriod=30,     //optional, do not set <30 sec.
    localSourceAddr="0.1.242"
]

Same issue described here by @lewie : https://github.com/calimero-project/calimero-core/issues/33

This is drive me crazy...

If there is something I can do to help I'm available

Thank you for your help in advance...

bmalinowsky commented 3 years ago

Why do you set localSourceAddr? Unless you have a reason to, don't do that for tunneling.

Anyway, from your log I don't see that a confirmation was sent. What you can try is the following: download Wireshark, select the network interface for 192.168.7.101, then, in the text control "Apply a display filter" insert "kip" and see if a confirmation is received for the sequence you have shown above (or post the corresponding wshark log here). Depending on whether there actually is a confirmation, one could proceed.

villaRob commented 3 years ago

Thanks @bmalinowsky, I already tried with wireshark, the missing confirmation depended on a wrong cEMI frame sent by my KNX-IP interface (WEINZIERL KNX IP BAOS 771). This wrong packet was discarded from calimero library I guess

I wrote to the Weinzierl and they reflashed device with a new firmware and resend back to me. So, seems that root cause of those problems was a bug in that old firmware. Now I have two instances of openhab (1.8 and 3) running without problem without localSourceAddr set as you seggested.

Thanks!

bmalinowsky commented 3 years ago

@PBrou did you fix the problem with your server? Does this issue still occur?

bmalinowsky commented 3 years ago

Closing due to inactivity.

PBrou commented 3 years ago

I must admit I took the easy way out: I bought a Gira IP router instead. No further testing was done on mentioned setup. Greetz Peter

Op 11 mrt. 2021 om 14:26 heeft bmalinowsky @.***> het volgende geschreven:

 @PBrou did you fix the problem with your server? Does this issue still occur?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub, or unsubscribe.