Core: KNX reaction is slow and unreliable
The problem
After update to 0.116.4 and updating config to work with my KNX setup I find it's behavior is kinda degraded. Light devices are now switched on and off with visible delay, though before update it was almost instant, but the main problem that made me open this issue is lag of binary switches. HA doesn't react to KNX button presses at all, until I switch something KNX related in HA interface. Then, it seems, that it establishes connection, and binary sensors work again, with visible lag though (1-2 seconds). After some time I see in logs Heartbeat to KNX bus failed. Reconnecting. And my binary switches doesn't work again, until I switch something in the UI again. Tried restarting everything, doesn't help. As I mentioned prior, it is a working setup, and before update nothing of described above was present. This is very annoying because I can't switch third part of my lights, because they rely on HA to transmit commands between KNX and various platforms.
Environment
- Home Assistant Core release with the issue: 0.116.4
- Last working Home Assistant Core release (if known): can't tell for sure something before breaking changes were introduced
- Operating environment (OS/Container/Supervised/Core): Raspbian/Docker without supervisor
- Integration causing this issue: KNX
- Link to integration documentation on our website: https://www.home-assistant.io/integrations/knx/
Problem-relevant configuration.yaml
knx:
tunneling:
host: '192.168.10.55'
# port: '3671'
# local_ip: '192.168.10.80'
(commented out previously used option to see if this makes any difference (no it doesn't))
binary_sensor:
- name: Server room button
state_address: '1/0/4'
reset_after: 1000
Traceback/Error logs
Logger: xknx.log
Source: /usr/local/lib/python3.8/site-packages/xknx/io/tunnel.py:288
First occurred: 12:24:11 AM (1 occurrences)
Last logged: 12:24:11 AM
Heartbeat to KNX bus failed. Reconnecting.
Additional information
Using Eibmarkt KNX EIB IP Interface, monitoring group bus in ETS, no problems.
monte-monte
All 52 comments
Not sure if this is the same problem, but I experience similar issues after latest update. Every actuator just stopped working. I get motion sensor events only, sometimes slow, as you describe. So apparently KNX connection to the gateway is working, but only receiving, not sending.
mikepan-ovoenergy
on 23 Oct 2020
For what it's worth, I'm running 0.116.4 with only lights, sensors and binary_sensors and don't experience delays, using an Weinzierl BAOS 772 IP Interface, so no router, same with knxd on beagle-bone with KNX Cape.
cyberjunky
on 23 Oct 2020
I just set the xknx logger on debug level and started logging this:
Logger: xknx.log
Source: /usr/local/lib/python3.8/site-packages/xknx/io/tunnel.py:122
First occurred: 11:23:42 AM (16 occurrences)
Last logged: 11:24:29 AM
Could not connect to KNX. Retry in 3 seconds.
Hey there @julius2342, @farmio, @marvin-w, mind taking a look at this issue as its been labeled with an integration (knx) you are listed as a codeowner for? Thanks!
(message by CodeOwnersMention)
![probot-home-assistant[bot] picture](https://avatars2.githubusercontent.com/in/36093?v=4&s=40)
probot-home-assistant[bot]
on 23 Oct 2020
For the binary_sensor delays configure ignore_internal_state = False or context_timeout = 0.
The unreliable connection could come from a problem with the state_updater - this needs an update of the xknx library in HA. The PR for this was not merged before start of 0.117 so it will take some weeks to fix it.
see https://github.com/home-assistant/core/pull/42026
farmio
on 23 Oct 2020
@farmio but it says in description "The parameter context_timeout is now optional for binary sensors and will default to None" and "The parameter ignore_internal_state for binary sensors now defaults to False" so setting it manually to false should not make any difference. Or am I missing something?
monte-monte
on 23 Oct 2020
this will be true after this PR is merged to HA.... so I guess in 0.118
You are quoting a breaking change note for a future version.
farmio
on 23 Oct 2020
@farmio well, it is in documentation already, so it's little confusing. I will try adding this now.
monte-monte
on 23 Oct 2020
Current documentation (your link) says default for ignore_internal_state is True and context_timeout is 1. These defaults will be changed in the linked PR.
farmio
on 23 Oct 2020
@farmio, any workaround or things to try? My whole setup is KNX based :( Strange thing is some KNX sensors are working fine and status updates are shown in HA. Problem is with KNX commands out of HA to actuators.
mikepan-ovoenergy
on 23 Oct 2020
@mikepan-ovoenergy you'll need to provide way more information (like configuration, environment and full logs) to get a clue what is causing this errors. Maybe in a separate issue at https://github.com/xknx/xknx
farmio
on 23 Oct 2020
@farmio you're right, apparently I can't read :)
Setting ignore_internal_state to flase helped with binary_sensor delay, thanks a lot!
monte-monte
on 23 Oct 2020
I also discovered issues with knx binary sensors in 0.116.4 (state updates delayed or not executed at all), but setting context_timeout: 0 and ignore_internal_state: false seems to fix it. Thanks for the workaround!
FireFrei
on 24 Oct 2020
i have set up this weekend my binary sensors in HA 0.116.4. After some time I get the following errors.
2020-10-25 19:36:12 WARNING (MainThread) [xknx.log] CEMI not supported: <UnsupportedCEMIMessage description="APCI not supported: 0b1111000000" />
2020-10-25 19:36:12 ERROR (MainThread) [xknx.log] <CouldNotParseKNXIP description="KNXIP data has wrong length" />
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/xknx/io/udp_client.py", line 86, in data_received_callback
knxipframe.from_knx(raw)
File "/usr/local/lib/python3.8/site-packages/xknx/knxip/knxip.py", line 80, in from_knx
raise CouldNotParseKNXIP("KNXIP data has wrong length")
xknx.exceptions.exception.CouldNotParseKNXIP: <CouldNotParseKNXIP description="KNXIP data has wrong length" />
2020-10-25 19:36:13 WARNING (MainThread) [xknx.log] CEMI not supported: <UnsupportedCEMIMessage description="APCI not supported: 0b1111000000" />
2020-10-25 19:36:13 ERROR (MainThread) [xknx.log] <CouldNotParseKNXIP description="KNXIP data has wrong length" />
Traceback (most recent call last):
File "/usr/local/lib/python3.8/site-packages/xknx/io/udp_client.py", line 86, in data_received_callback
knxipframe.from_knx(raw)
File "/usr/local/lib/python3.8/site-packages/xknx/knxip/knxip.py", line 80, in from_knx
raise CouldNotParseKNXIP("KNXIP data has wrong length")
xknx.exceptions.exception.CouldNotParseKNXIP: <CouldNotParseKNXIP description="KNXIP data has wrong length" />
2020-10-25 19:37:13 WARNING (MainThread) [xknx.log] Heartbeat to KNX bus failed. Reconnecting.
Then no more status changes arrive at HA. (motion, brightness, temperature, binary)
However, when I manually switch on a light in HA, everything runs again for a certain time.
i also tried the tip with context_timeout and ignore_internal_state but unfortunately i don't see any change.
webman2030
on 25 Oct 2020
@webman2030 something is sending awkward telegrams on your bus (UnsupportedCEMIMessage). You can use ETS or Wireshark to see the origin of these telegrams. Sometimes ETS itself can send such packets eg. when looking for devices in programming mode. This can cause problems for the knx integration under some circumstances (I could never reproduce this on my system).
farmio
on 25 Oct 2020
@farmio
i found out that my ip-interface (MDT SCN-IP000.03) syncs the time/date exactly every 10 minutes.
The times which show me ETS and HA are identical.
I have now deactivated the synchronization, I hope that was it.
EDIT: Same as here
https://github.com/XKNX/xknx/issues/408
webman2030
on 25 Oct 2020
@webman2030 not exactly the same, as your ETS seems to be able to decode the payload (this was not the case in 408). Can you post the raw data of the telegram causing the issues - when you know for sure which one it is (eg. from ETS properties tab or xknx.raw_socket logger)?
The xknx loggers on debug level will help you find it:
xknx.raw_socketwill log everything received in rawxknx.knxwill log every decoded telegram (the one causing the issue will not log this)
farmio
on 25 Oct 2020
I had the same issue as @monte-monte and @FireFrei , knx unreliable and actuators and sensors are behaving completely randomly. E.g a PIR sensor had no clue that I just walked into a room. (At least on the HA side, ETS5 perfectly shows that someone walked into that room). Problem started since version 0.163 or 0.164. Before that KNX worked very stable and quick within HA.
I did include the following config parameters with each binary sensor:
context_timeout: 0 and ignore_internal_state: false
And that seems (after 1 day testing) to solve the problem for now.
Although I did notice that I needed to activate an actor from HA (writing a parameter), before the sensors (read a parameter) were able to send data to HA.
Just to inform, there are plenty of KNX errors in the log:
Heartbeat to KNX bus failed. Reconnecting.
4:14:17 PM – /usr/local/lib/python3.8/site-packages/xknx/io/tunnel.py (WARNING) - message first occurred at October 24, 2020, 11:59:16 PM and shows up 20 times
Source: /usr/local/lib/python3.8/site-packages/xknx/remote_value/remote_value.py:175
First occurred: October 24, 2020, 11:58:08 PM (38 occurrences)
Last logged: 3:58:14 PM
Could not sync group address '5/0/11' (Slaapkamer M&M Temperatuur - Value)
Could not sync group address '5/0/8' (Gang Boven PIR - State)
Could not sync group address '1/3/1' (Lichtbalk Badkamer - Brightness)
Could not sync group address '5/0/4' (Slaapkamer Friso Temperatuur - Value)
Could not sync group address '5/0/2' (Slaapkamer Valentijn PIR - State)
Source: /usr/local/lib/python3.8/site-packages/xknx/core/value_reader.py:70
First occurred: October 24, 2020, 11:58:08 PM (38 occurrences)
Last logged: 3:58:14 PM
Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 5/0/11
Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 5/0/8
Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 1/3/1
Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 5/0/4
Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 5/0/2
Holland1
on 26 Oct 2020
Did some more testing, but KNX remains unreliable. It's likely the result of a lost connection. See the log entry below.
Ones the connection is lost, all the sensors stop communicating, and only when I send a signal (from HA) to an actuator, the connection is restored and all sensors work as expected.
Heartbeat to KNX bus failed. Reconnecting.
2:14:20 PM – /usr/local/lib/python3.8/site-packages/xknx/io/tunnel.py (WARNING) - message first occurred at October 26, 2020, 10:13:42 PM and shows up 12 times
Holland1
on 27 Oct 2020
An update on KNX instability;
The log below shows that KNX has been disconnected, for more than 20 minutes. It reconnected automatically.
`2020-10-30 00:48:41 WARNING (MainThread) [xknx.log] Heartbeat to KNX bus failed. Reconnecting.
2020-10-30 01:10:13 WARNING (MainThread) [xknx.log] Error: KNX bus did not respond in time (2 secs) to GroupValueRead request for: 3/2/0
2020-10-30 01:10:13 WARNING (MainThread) [xknx.log] Could not sync group address '3/2/0' (Slaapkamer M&M Rolgordijn Links Open/Dicht - Position)
2020-10-30 01:10:13 INFO (MainThread) [xknx.log] Successfully reconnected to KNX bus.
2020-10-30 01:52:36 WARNING (MainThread) [xknx.log] Heartbeat to KNX bus failed. Reconnecting.`
Holland1
on 30 Oct 2020
@Holland1 use xknx debug log level to find out what is causing these disconnects.
Or use ETS diagnostics group address monitor.
farmio
on 30 Oct 2020
@farmio Please find configuration.yaml and xknx log below ;
configuration.yaml
knx:
tunneling:
host: '10.58.60.11' #knx ip gateway
port: 3671
light:
- name: Lichtbalk WC Boven
address: '1/1/1'
state_address: '1/4/0'
brightness_address: '1/2/1'
brightness_state_address: '1/3/0'
- name: Lichtbalk Badkamer
address: '1/1/2'
state_address: '1/4/1'
brightness_address: '1/2/2'
brightness_state_address: '1/3/1'
cover:
- name: "Slaapkamer M&M Rolgordijn Links Open/Dicht"
move_long_address: '3/0/0'
move_short_address: '3/1/0' # If th
etc...
#
2020-10-30 09:10:03 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:03 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:03 INFO (MainThread) [homeassistant.components.automation.1_11_0_wwitch_light_lichtbalk_wc_boven_when_light_wc_boven_is_switched_on] 1.11.0 Wwitch_light_lichtbalk_wc_boven_when_light_wc_boven_is_switched_on: Executing step call service
2020-10-30 09:10:03 WARNING (MainThread) [homeassistant.components.system_log.external] The state of light.wc_boven_main Level light.fibaro_system_fgd211_universal_dimmer_500w_level_2 changed from off to on
2020-10-30 09:10:04 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Tunnelling'
2020-10-30 09:10:04 DEBUG (MainThread) [xknx.log] Sending of telegram failed. Retrying a second time.
2020-10-30 09:10:04 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Tunnelling'
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Resending telegram failed. Reconnecting to tunnel.
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 0610020a00081021
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Tunnel disconnected (communication_channel: 16)
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061002060014100008010a3a3c0b0e57040411ff
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.log] Tunnel established communication_channel=16, id=4607
2020-10-30 09:10:05 INFO (MainThread) [xknx.log] Successfully reconnected to KNX bus.
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 06100421000a04100000
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200015041000002e00bce011ff0901010081
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:05 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200015041001002900bce011060c00010081
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200016041002002900bce011060b0002008008
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:06 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:07 INFO (MainThread) [custom_components.visonic.pyvisonic] [data receiver] * Received validated message 0XA5
2020-10-30 09:10:07 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200016041003002900bce011060b0002008043
2020-10-30 09:10:07 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:07 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:07 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:08 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200016041004002900bce011060b0002008083
2020-10-30 09:10:08 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:08 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:08 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:09 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200016041005002900bce011060b00020080c3
2020-10-30 09:10:09 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:09 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:09 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:10 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200016041006002900bce011060b00020080ff
2020-10-30 09:10:10 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:10 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:10 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:12 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200015041007002900bce011082808010080
2020-10-30 09:10:12 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:12 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:12 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:13 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200017041008002900bce01108280903008004b0
2020-10-30 09:10:13 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:13 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:13 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:20 INFO (MainThread) [custom_components.visonic.pyvisonic] [data receiver] Received validated message 0XA5 *
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061004200015041009002900b4e011052803010080
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.telegram]
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.knx] Sending:
body="
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 0610020800081000
2020-10-30 09:10:20 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:23 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 06100420001504100a002900b4e011052803010081
2020-10-30 09:10:23 DEBUG (MainThread) [xknx.knx] Received:
body="
2020-10-30 09:10:23 DEBUG (MainThread) [xknx.knx] Sending:
body="
Holland1
on 30 Oct 2020
@Holland1
we'd need to know what happens right before these first coulple lines of your log. Up to 15 seconds before there must be something where the connection was lost - I guess an exception, unsupported frame or a DisconnectRequest. This would be the interesting part.
# here you try to send a Telegram
2020-10-30 09:10:03 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/1")", payload="" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.OUTGOING" />
# same Telegram, different logger (and layer)
2020-10-30 09:10:03 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame
body="<TunnellingRequest communication_channel_id="16" sequence_counter="21" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.255")" DestinationAddress="GroupAddress("1/1/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="" />" />" />
# not intresting to us
2020-10-30 09:10:03 INFO (MainThread) [homeassistant.components.automation.1_11_0_wwitch_light_lichtbalk_wc_boven_when_light_wc_boven_is_switched_on] 1.11.0 Wwitch_light_lichtbalk_wc_boven_when_light_wc_boven_is_switched_on: Executing step call service
2020-10-30 09:10:03 WARNING (MainThread) [homeassistant.components.system_log.external] The state of light.wc_boven_main Level light.fibaro_system_fgd211_universal_dimmer_500w_level_2 changed from off to on
# The telegram was sent, but no Ack was received - so it never reached the tunnelling server -> we had no functioning tunnelling connection when we tried to send the Telegram before
2020-10-30 09:10:04 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Tunnelling'
2020-10-30 09:10:04 DEBUG (MainThread) [xknx.log] Sending of telegram failed. Retrying a second time.
# ... later on the Tunnelling connection will be reconnected and works again
The rest of the log seems like everything is working then.
farmio
on 30 Oct 2020
I apologize, I don't have the log from above anymore. I tried to troubleshoot a few things, e.g autodiscover the knx gateway, and therefore I needed tot restart HA.
configuration.yaml
knx:
#tunneling:
#host: '10.58.60.11' #knx ip gateway
#port: 3671
light:
- name: Lichtbalk WC Boven
address: '1/1/1'
state_address: '1/4/0'
brightness_address: '1/2/1'
brightness_state_address: '1/3/0'
- name: Lichtbalk Badkamer
address: '1/1/2'
state_address: '1/4/1'
brightness_address: '1/2/2'
brightness_state_address: '1/3/1'
cover:
- name: "Slaapkamer M&M Rolgordijn Links Open/Dicht"
move_long_address: '3/0/0'
move_short_address: '3/1/0' # If the
etc................
#
Couldn't get the markup properly here, despite using ``
So see the link below
Holland1
on 30 Oct 2020
@Holland1 well, I don't see why the disconnect happens, just that it does. There was nothing special going on. Just a telegram comming in twice form 1.1.3 for 5/0/1
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 06100420001704114f002900bce0110328010300801d02
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="17" sequence_counter="79" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.3")" DestinationAddress="GroupAddress("5/0/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0x1d,0x2]" />" />" />" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="17" sequence_counter="79" status_code="ErrorCode.E_NO_ERROR" />" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("5/0/1")", payload="<DPTArray value="[0x1d,0x2]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 06100420001704114f002900bce0110328010300801d02
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="17" sequence_counter="79" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.3")" DestinationAddress="GroupAddress("5/0/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0x1d,0x2]" />" />" />" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="17" sequence_counter="79" status_code="ErrorCode.E_NO_ERROR" />" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("5/0/1")", payload="<DPTArray value="[0x1d,0x2]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.raw_socket] Received from ('10.58.60.11', 3671): 061002090010110008010a3a3c0b0e57
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="17" control_endpoint="<HPAI 10.58.60.11:3671 />" />" />
2020-10-30 11:18:17 DEBUG (MainThread) [xknx.log] UNHANDLED: KNXIPServiceType.DISCONNECT_REQUEST
sorry, can't help you with this.
farmio
on 30 Oct 2020
But is that DISCONNECT_REQUEST coming from the gateway ?
Holland1
on 30 Oct 2020
Yes.
Xknx doesn't handle these yet. But shortly after the disconnect request the connection is gone (normally there should be a DisconnectResponse).
farmio
on 30 Oct 2020
Okay, I've caught this bug again and find log entries that was preceding it. I don't know if this helps in any way.
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610042000170445e1002900bce0113209050300800d14
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="69" sequence_counter="225" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.50")" DestinationAddress="GroupAddress("1/1/5")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0xd,0x14]" />" />" />" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="69" sequence_counter="225" status_code="ErrorCode.E_NO_ERROR" />" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/5")", payload="<DPTArray value="[0xd,0x14]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610042000170445e1002900bce0113209050300800d14
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="69" sequence_counter="225" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.50")" DestinationAddress="GroupAddress("1/1/5")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0xd,0x14]" />" />" />" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="69" sequence_counter="225" status_code="ErrorCode.E_NO_ERROR" />" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/5")", payload="<DPTArray value="[0xd,0x14]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 06100209001045450801c0a80a370e57
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="69" control_endpoint="<HPAI 192.168.10.55:3671 />" />" />
2020-10-30 10:19:40 DEBUG (MainThread) [xknx.log] UNHANDLED: KNXIPServiceType.DISCONNECT_REQUEST
2020-10-30 10:19:43 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="69", control_endpoint="<HPAI 192.168.10.80:33047 />" />" />
2020-10-30 10:19:43 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800084521
2020-10-30 10:19:43 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="69" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-10-30 10:19:43 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 10:19:58 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="69", control_endpoint="<HPAI 192.168.10.80:33047 />" />" />
2020-10-30 10:19:58 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800084521
2020-10-30 10:19:58 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="69" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-10-30 10:19:58 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 10:20:13 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="69", control_endpoint="<HPAI 192.168.10.80:33047 />" />" />
2020-10-30 10:20:13 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800084521
2020-10-30 10:20:13 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="69" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-10-30 10:20:13 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="69", control_endpoint="<HPAI 192.168.10.80:33047 />" />" />
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800084521
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="69" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 10:20:28 WARNING (MainThread) [xknx.log] Heartbeat to KNX bus failed. Reconnecting.
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="69" control_endpoint="<HPAI 192.168.10.80:33047 />" />" />
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020a00084521
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_RESPONSE" Reserve="0" TotalLength="8" />
body="<DisconnectResponse CommunicationChannelID="69" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-10-30 10:20:28 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-10-30 10:20:29 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Disconnect'
I see DISCONNECT_REQUEST 10 times in the current log, but only once it results in described bug.
monte-monte
on 31 Oct 2020
@monte-monte this is essentially the same as above. A telegram is incoming twice, the ACK is sent twice from xknx and then the DisconnectRequest comes in.
No idea why the exact same telegram (same sequence number) is incoming twice (in the same second - no milliseconds logged).
Im not entirely sure if it's appropriate to ACK twice under these circumstances. I'll have a look in the specs when there is time.
Handling this correctly is one thing, but it doesn't explain why the telegram was repeated in the first place.
For those who can handle git, shell and Python: you could try the xknx custom component with xknx 0.15.3 - there are already some changes to StateUpdater and tunnel stability (mostly for when programming from ETS). Maybe this helps here too - it's worth a try and we'd need some field-tests 😉
Edit: sending the ACK twice complies with the KNX standard.
If a KNXnet/IP Tunnelling Client receives a frame with a sequence number that is one less than the expected sequence number then it shall reply with a TUNNELLING_ACK (Status = E_NO_ERROR) message and discard the received frame.
farmio
on 31 Oct 2020
@farmio
I will start to setup an environment to test 0.15.3, compile python 3.8 etc. Will report back soon
p.s thanks for helping us out with this issue. My HA install worked without any issues for more than to a year. Issues started a couple of weeks ago, but not sure from which version it started.
Holland1
on 31 Oct 2020
@farmio Takes a bit longer, pre-commit is not cooperating :(
Holland1
on 31 Oct 2020
You don't need to compile/build anything. Any Python running HA will do. xknx 0.15.3 can be installed from pypi with pip.
To load the custom component see https://xknx.io/home_assistant.html (I think it doesn't work with hassio)
farmio
on 31 Oct 2020
@farmio
Indeed, doesn't work in hassio. Found that out a few hours later :)
Did setup a new HA environment on raspbian, and xknx 0.15.3 is running now.
Although just 3 hours of testing, the connection errors have not returned (yet). I will continue the test and share the log.
Holland1
on 1 Nov 2020
@Holland1 👍
These errors seem legit. They are always the same GAs. Are they readable from ETS / your Tunnelling connection (if you run multiple KNX lines)? Do they have R-Flags set? Do you see a GroupValueRead and GroupValueResponse in ETS for these GAs?
farmio
on 1 Nov 2020
@farmio
It looks like the sync issue is always with the same GA's. But, these addresses are perfectly readable from within ETS(if you request to read the value) and from xknx. Have a look to screenshot below, right after starting HA.
Both 3/2/0 and 3/2/1 are covers, and linked to position_state_address. As you can see, at 1:04:50:282 xknx sends a readrequest to 3/2/0, and knx responds immediately 0%. 3/2/1 responds with 100%. Is it maybe the case that xknx expects the return of a binary value like on or off?
1/4/0 is a LED strip status GA linked to state_address. After reading by xknx it returns, Active.
Strange enough, 1/4/1 is a copy of 1/4/0 (exactly the same config, different device), and is not giving this error.
The R flag is set for all GA's
Holland1
on 2 Nov 2020
@farmio
Still running smoothly after running for 16 hours, no disconnects so far. It looks very promising.
About these KNX did not respond in 1 sec errors, see link below.
Are these errors maybe related to the local time differences between KNX IP gateway and the xknx system?
For example, GA 3/2/0 is read on the xknx system @ 17:26:09, while ETS answers @ 17:26:13.66
Both the xknx system and the knx ip gateway use the same NTP server, and are in sync.
Holland1
on 2 Nov 2020
Are these errors maybe related to the local time differences between KNX IP gateway and the xknx system?
Both the xknx system and the knx ip gateway use the same NTP server, and are in sync.
So are they in sync, or are they drifted 4 seconds? I don't think it really matters. xknx starts a timer for 1 second after scheduling the request. Local time isn't accounted anywhere here, but if the request is scheduled 4 seconds after it is received by ETS there is some kind of problem.
Can you enable debug logging for xknx again so we can see when the request goes out and if/when the response is received on the HA device.
You could also run eg. wireshark on your test installation device to capture knx packets if you like.
farmio
on 2 Nov 2020
Can you enable debug logging for xknx again so we can see when the request goes out and if/when the response is received on the HA device.
Have a look at the log https://pastebin.com/ggt3Kytm . Please jump to row 830. I switched off a light (1/1/1) from HA @ 21:30:43.
Screenshot below shows that the request is received in < 1 sec. @ 9:30:43.422
Now for the xknx sync erros while starting HA. Please jump to row 123. A request to read 3/2/0 is send out at 21:24:50.
The bus receives it at 9:24:53.166 and sends a message back at 9:24:53.219. Couldn't be better, I would say.
But then, xknx receives the message at 2020-11-02 21:24:53 on row 139. It looks like HA was loading a bunch of other stuff, so xknx didn't have time to work on the message earlier.
Holland1
on 2 Nov 2020
🤔 there are some
[homeassistant.setup] Setup of domain ... took 1.0 seconds
before 123. Does it happen when you don't load (disable) these too? If not then you are probably right.
Maybe it's even one specific domain blocking for a second or too at loading.
farmio
on 2 Nov 2020
Does it happen when you don't load (disable) these too? Will test this later on
Is there a logical explanation for the "Could not sync group address" errors? See also my post yesterday evening; https://github.com/home-assistant/core/issues/42238#issuecomment-720177940
Holland1
on 2 Nov 2020
Nope. position_state_address is DPT 5, that is correct.
You can try to change order of your configured covers etc. and see if it is still the Same GA, but I'd try to disable everything but knx and see if it still can't be read. Then one by one enable other domains.
It seems there is a delay between starting the timer and sending out the telegram. But I can't really say where this is introduced yet...
Why is your HA's IA 15.15.255? Do you have multiple lines and line couplers/routers? Your interface should assign a sane IA when connecting, but these may have to be configured from ETS / web interface once. See your interface manual. (I doubt this is the reason if you have just one line).
farmio
on 3 Nov 2020
You can try to change order of your configured covers etc. and see if it is still the Same GA, but I'd try to disable everything but knx and see if it still can't be read.
I will try that and report back
Why is your HA's IA 15.15.255?
Not sure, it's likely the default value for a MDT IP interface. Or, maybe I have just chosen a random address when I first started to use KNX. Will change in something that is more logical/applicable.
Do you have multiple lines and line couplers/routers?
No just 1 IP interface, no LC's
Now the only thing that is left is getting xknx 0.15.3 into the HA dev branch and
Is there any possibility to highlight the importance of this PR to the HA maintainers, as xknx 0.15.0 breaks the knx implementation of many?
Holland1
on 3 Nov 2020
@farmio Is there any chance that 0.15.3 will hit 0.118 or will this take longer.
I need decide if downgrading to 0.114.4 is the best option, or that I should wait a bit longer.
Holland1
on 6 Nov 2020
We are planning to update our 0.15.2 update PR to include 0.15.3 too (maybe tonight). But we can't say when HA will review/approve it.
I'd just keep running the custom component until it is merged and released.
farmio
on 6 Nov 2020
Excellent. Thanks for the hard work/effort.
I'd just keep running the custom component until it is merged and released.
Not that easy, production server is running hassio
Holland1
on 6 Nov 2020
Maybe you can review https://github.com/home-assistant/core/pull/42026 to reduce work for HA maintainers and speed things up.
farmio
on 6 Nov 2020
Have found no issues.
this also eliminates a lot of bugs introduces since HA 0.115 and should provide much more stable tunnelling connections
Maybe good to also include the label bugfix, hopefully it's picked up sooner by the maintainers this way
Holland1
on 7 Nov 2020
Spent some time to migrate from docker to local HA install to try xknx 0.15.3. Bug is still present in my case no difference from built-in xknx version in 0.117.5.
2020-11-11 23:48:38 INFO (MainThread) [xknx.log] XKNX v0.15.3 starting tunneling connection to KNX bus.
...
body="<DisconnectRequest CommunicationChannelID="27" control_endpoint="<HPAI 192.168.10.55:3671 />" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.log] UNHANDLED: KNXIPServiceType.DISCONNECT_REQUEST
2020-11-11 23:52:47 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="27", control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:52:47 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800081b21
2020-11-11 23:52:47 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-11 23:52:47 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-11-11 23:53:02 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="27", control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:53:02 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800081b21
2020-11-11 23:53:02 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-11 23:53:02 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-11-11 23:53:17 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="27", control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:53:17 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800081b21
2020-11-11 23:53:17 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-11 23:53:17 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="27", control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800081b21
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'ConnectionState' with error in 'ConnectionStateResponse': ErrorCode.E_CONNECTION_ID
2020-11-11 23:53:32 WARNING (MainThread) [xknx.log] Heartbeat to KNX bus failed. Reconnecting.
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="27" control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020a00081b21
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_RESPONSE" Reserve="0" TotalLength="8" />
body="<DisconnectResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-11 23:53:32 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-11-11 23:53:33 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Disconnect'
As soon as Heartbeat to KNX bus failed. communication between HA and KNX tunnel is lost.
I even wanted to make automation based on this error message, but it seem that only system log message can fire events which can be used in automation.
I will try to send telegrams to dummy addresses to keep connection alive in case it drops again. But I hope that better solution can be found.
Just to be complete, this is a log after I engage KNX device via HA web interface to bring connection alive:
2020-11-12 00:20:43 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/3/1")", payload="<DPTBinary value="False" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.OUTGOING" />
2020-11-12 00:20:43 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="27" sequence_counter="36" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.10")" DestinationAddress="GroupAddress("1/3/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTBinary value="False" />" />" />" />
2020-11-12 00:20:44 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Tunnelling'
2020-11-12 00:20:44 DEBUG (MainThread) [xknx.log] Sending of telegram failed. Retrying a second time.
2020-11-12 00:20:44 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="27" sequence_counter="36" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.10")" DestinationAddress="GroupAddress("1/3/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTBinary value="False" />" />" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Error: KNX bus did not respond in time (1 secs) to request of type 'Tunnelling'
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Resending telegram failed. Reconnecting to tunnel.
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="27" control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020a00081b21
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_RESPONSE" Reserve="0" TotalLength="8" />
body="<DisconnectResponse CommunicationChannelID="27" status_code="ErrorCode.E_CONNECTION_ID" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Error: KNX bus responded to request of type 'Disconnect' with error in 'DisconnectResponse': ErrorCode.E_CONNECTION_ID
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Tunnel disconnected (communication_channel: 27)
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECT_REQUEST" Reserve="0" TotalLength="26" />
body="<ConnectRequest control_endpoint="<HPAI 192.168.10.80:45156 />" data_endpoint="<HPAI 192.168.10.80:45156 />" request_type="ConnectRequestType.TUNNEL_CONNECTION" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020600141c000801c0a80a370e570404110a
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECT_RESPONSE" Reserve="0" TotalLength="20" />
body="<ConnectResponse communication_channel="28" status_code="ErrorCode.E_NO_ERROR" control_endpoint="<HPAI 192.168.10.55:3671 />" request_type="ConnectRequestType.TUNNEL_CONNECTION" identifier="4362" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.log] Tunnel established communication_channel=28, id=4362
2020-11-12 00:20:46 INFO (MainThread) [xknx.log] Successfully reconnected to KNX bus.
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="28" sequence_counter="0" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.10")" DestinationAddress="GroupAddress("1/3/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTBinary value="False" />" />" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 06100421000a041c0000
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="28" sequence_counter="0" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 061004200015041c00002e00bce0110a0b01010080
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="28" sequence_counter="0" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.10")" DestinationAddress="GroupAddress("1/3/1")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTBinary value="0" />" />" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="28" sequence_counter="0" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 061004200015041c01002900bce0116e0b09010080
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="28" sequence_counter="1" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.110")" DestinationAddress="GroupAddress("1/3/9")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTBinary value="0" />" />" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="28" sequence_counter="1" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-12 00:20:46 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/3/9")", payload="<DPTBinary value="0" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
So when it tells Heartbeat to KNX bus failed. Reconnecting. it actually doesn't reconnect, because Successfully reconnected to KNX bus. message is logged only after outgoing telegram.
monte-monte
on 11 Nov 2020
@monte-monte this is the point your connection is lost:
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.log] UNHANDLED: KNXIPServiceType.DISCONNECT_REQUEST
its the 2nd line of your log above. It would be good to know what happened before.
What is going on besides home assistant? Any other software trying to connect to the interface at the same time? What is your setup (eg. any Wifi, etc. involved between HA and knx interface)?
farmio
on 12 Nov 2020
@farmio KNX tunnel is used only by HA, both are connected via ethernet through unmanaged switch. Accessing tunnel with ETS from a laptop shows no issues. KNX interface is "Weizel KNXIP Interface730" https://www.weinzierl.de/images/download/products/730/Weinzierl_730_KNX_IP_Interface_Manual_EN.pdf It has no settings except manual or dynamic IP.
The part you asked for:
2020-11-11 23:52:23 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 061004200017041b49002900bce0113209050300800d14
2020-11-11 23:52:23 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="27" sequence_counter="73" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.50")" DestinationAddress="GroupAddress("1/1/5")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0xd,0x14]" />" />" />" />
2020-11-11 23:52:23 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="27" sequence_counter="73" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-11 23:52:23 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/5")", payload="<DPTArray value="[0xd,0x14]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-11-11 23:52:32 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="27", control_endpoint="<HPAI 192.168.10.80:51551 />" />" />
2020-11-11 23:52:32 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020800081b00
2020-11-11 23:52:32 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="27" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 061004200017041b4a002900bce0113209050300800ce2
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="27" sequence_counter="74" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.50")" DestinationAddress="GroupAddress("1/1/5")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0xc,0xe2]" />" />" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="27" sequence_counter="74" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/5")", payload="<DPTArray value="[0xc,0xe2]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 061004200017041b4a002900bce0113209050300800ce2
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_REQUEST" Reserve="0" TotalLength="23" />
body="<TunnellingRequest communication_channel_id="27" sequence_counter="74" cemi="<CEMIFrame SourceAddress="PhysicalAddress("1.1.50")" DestinationAddress="GroupAddress("1/1/5")" Flags="1011110011100000" Command="APCICommand.GROUP_WRITE" payload="<DPTArray value="[0xc,0xe2]" />" />" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.knx] Sending: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="27" sequence_counter="74" status_code="ErrorCode.E_NO_ERROR" />" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.telegram] <Telegram group_address="GroupAddress("1/1/5")", payload="<DPTArray value="[0xc,0xe2]" />" telegramtype="TelegramType.GROUP_WRITE" direction="TelegramDirection.INCOMING" />
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.10.55', 3671): 0610020900101b1b0801c0a80a370e57
2020-11-11 23:52:38 DEBUG (MainThread) [xknx.knx] Received: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="KNXIPServiceType.DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="27" control_endpoint="<HPAI 192.168.10.55:3671 />" />" />
EDIT:
1/1/50 address is a Mitsubishi AC connected via "IntesisBox ME AC" adapter. It periodically sends current temperature (1/1/5). I don't know if this could be somehow connected to the issue.
monte-monte
on 12 Nov 2020
I have same issue, I have installed my KNXnet/IP interface (Enertex). My system is running on a Pi4 4GB
I have tried to ping the interface continously with no errors, at the same time I got errors in the log.
SofaSurfer76
on 12 Nov 2020
Bug is still present in 0.118.1
Nothing changed at all.
monte-monte
on 21 Nov 2020
Related issues
sagilo
·
130Comments
kdschlosser
·
374Comments
abouelric
·
165Comments
nodkan
·
161Comments
aguilaair
·
162Comments