core: knx tunneling connection loss - time/date no longer exposed - reconnect should not trigger automation
The problem
HA seems to drop within 1-2 days after a restart the tunneling connection to my KNX IP gateway (Weizierl KNX IP BAOS 772). This leads to 2 problems:
- HA is exposing the time/date on the KNX bus. After reconnecting, this no longer seems to be working (my GIRA wall switches indicate they are not receiving time-updates). A restart of HA is needed to re-expose the time to the KNX bus
- I have a few Wifi wall socket switches (Sonoff S20 running Tasmota) that are switched on/off with a HA-automation when a certain KNX-scenario is activated. For example: an automation turns off certain sockets when a KNX ‘night’-scenario has been activated. The KNX-connection loss seems to trigger this automation, resulting in a quick switch on and off, although the automation only contains an action to switch off the socket.
What version of Home Assistant Core has the issue?
core-2022.3.7
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant Container
Integration causing the issue
knx
Link to integration documentation on our website
https://www.home-assistant.io/integrations/knx/
Diagnostics information
config_entry-knx-28c60dd0515f3e0a436bbaf149f3a85b.json (1).txt
Example YAML snippet
No response
Anything in the logs that might be useful for us?
I am including the log file of the connection loss that happened this morning at 6:23:
2022-04-05 06:22:22 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132542.6317146:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECTIONSTATE_REQUEST" Reserve="0" TotalLength="16" />
body="<ConnectionStateRequest CommunicationChannelID="72", control_endpoint="192.168.1.12:56975/udp" />" />
2022-04-05 06:22:22 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 0610020800084800
2022-04-05 06:22:22 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132542.6371832:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECTIONSTATE_RESPONSE" Reserve="0" TotalLength="8" />
body="<ConnectionStateResponse CommunicationChannelID="72" status_code="ErrorCode.E_NO_ERROR" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 0610042000160448c1002900bce0110f130202008019
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132598.3190699:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_REQUEST" Reserve="0" TotalLength="22" />
body="<TunnellingRequest communication_channel_id="72" sequence_counter="193" cemi="<CEMIFrame SourceAddress="IndividualAddress("1.1.15")" DestinationAddress="GroupAddress("2/3/2")" Flags="1011110011100000" code="L_DATA_IND" payload="<GroupValueWrite value="<DPTArray value="[0x19]" />" />" />" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132598.3197277:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="72" sequence_counter="193" status_code="ErrorCode.E_NO_ERROR" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.telegram] <Telegram direction="Incoming" source_address="1.1.15" destination_address="2/3/2" payload="<GroupValueWrite value="<DPTArray value="[0x19]" />" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 0610042000160448c1002900bce0110f130202008019
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132598.3371336:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_REQUEST" Reserve="0" TotalLength="22" />
body="<TunnellingRequest communication_channel_id="72" sequence_counter="193" cemi="<CEMIFrame SourceAddress="IndividualAddress("1.1.15")" DestinationAddress="GroupAddress("2/3/2")" Flags="1011110011100000" code="L_DATA_IND" payload="<GroupValueWrite value="<DPTArray value="[0x19]" />" />" />" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132598.3378189:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="72" sequence_counter="193" status_code="ErrorCode.E_NO_ERROR" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.telegram] <Telegram direction="Incoming" source_address="1.1.15" destination_address="2/3/2" payload="<GroupValueWrite value="<DPTArray value="[0x19]" />" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 06100209001048480801c0a801310e57
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132598.352643:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="DISCONNECT_REQUEST" Reserve="0" TotalLength="16" />
body="<DisconnectRequest CommunicationChannelID="72" control_endpoint="192.168.1.49:3671/udp" />" />
2022-04-05 06:23:18 WARNING (MainThread) [xknx.log] Received DisconnectRequest from tunnelling sever.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132598.3535402:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="DISCONNECT_RESPONSE" Reserve="0" TotalLength="8" />
body="<DisconnectResponse CommunicationChannelID="72" status_code="ErrorCode.E_NO_ERROR" />" />
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959802878896 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959803160992 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959809465744 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959801146480 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959830857184 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Stopping task datetime.broadcast_139959793463360 because of connection loss.
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.state_updater] StateUpdater stopping
2022-04-05 06:23:18 DEBUG (MainThread) [xknx.log] Closing transport.
2022-04-05 06:23:19 WARNING (MainThread) [homeassistant.components.automation.ventilatie] Ventilatie: Already running
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132601.6370552:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECT_REQUEST" Reserve="0" TotalLength="26" />
body="<ConnectRequest control_endpoint="192.168.1.12:33686/udp" data_endpoint="192.168.1.12:33686/udp" request_type="ConnectRequestType.TUNNEL_CONNECTION" />" />
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 06100206001449000801c0a801310e57040411fa
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132601.6427915:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECT_RESPONSE" Reserve="0" TotalLength="20" />
body="<ConnectResponse communication_channel="73" status_code="ErrorCode.E_NO_ERROR" data_endpoint="192.168.1.49:3671/udp" request_type="ConnectRequestType.TUNNEL_CONNECTION" identifier="4602" />" />
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Tunnel established communication_channel=73, address=1.1.250
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959802878896 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959803160992 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959809465744 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959801146480 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959830857184 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.log] Restarting task datetime.broadcast_139959793463360 as the connection to the bus was reestablished.
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.state_updater] StateUpdater initializing values
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.state_updater] StateUpdater reading 0/0/35 for Ketelcontact - State
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.state_updater] StateUpdater reading 2/6/0 for Temperatuur Voordeur - Value
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.telegram] <Telegram direction="Outgoing" source_address="1.1.250" destination_address="0/0/35" payload="<GroupValueRead />" />
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.knx] Sending to 192.168.1.49:3671 at 1649132601.8780334:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="73" sequence_counter="0" cemi="<CEMIFrame SourceAddress="IndividualAddress("1.1.250")" DestinationAddress="GroupAddress("0/0/35")" Flags="1011110011100000" code="L_DATA_REQ" payload="<GroupValueRead />" />" />" />
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 06100421000a04490000
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132601.908757:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_ACK" Reserve="0" TotalLength="10" />
body="<TunnellingAck communication_channel_id="73" sequence_counter="0" status_code="ErrorCode.E_NO_ERROR" />" />
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.raw_socket] Received from ('192.168.1.49', 3671): 061004200015044900002e00bce011fa0023010000
2022-04-05 06:23:21 DEBUG (MainThread) [xknx.knx] Received from 192.168.1.49:3671 at 1649132601.9369955:
<KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="TUNNELLING_REQUEST" Reserve="0" TotalLength="21" />
body="<TunnellingRequest communication_channel_id="73" sequence_counter="0" cemi="<CEMIFrame SourceAddress="IndividualAddress("1.1.250")" DestinationAddress="GroupAddress("0/0/35")" Flags="1011110011100000" code="L_DATA_CON" payload="<GroupValueRead />" />" />" />
Additional information
I have tried to work around the second problem by adding a delay to the automation (it should only trigger when the KNX-‘night’ scenario has been active for 2 seconds) but the problem persists. The wall sockets are still being switched on by the automation, although it only contains a “switch off” action.
About this issue
- Original URL
- State: closed
- Created 2 years ago
- Comments: 23 (8 by maintainers)
So we identified the issue and are working on a fix. It will need a new release of xknx - hopefully done until 2022.5 is released (xknx 0.21.0 used in coming beta 5 still has the issue). https://github.com/XKNX/xknx/pull/936
I reopened it. I will test it again when I have some time left.
I’ve installed 2022.4.7 and can confirm this bug is solved. Time & date are now again exposed to the KNX bus. Thanks everybody for solving this issue.
After almost a day with a stable tunnel connection (no reconnects), HA keeps exposing time to the KNX bus on an hourly basis. I think this confirms something goes wrong after HA has reconnected. Please let me know if there is anything further I can do to help.
In the log I attached to my previous post, I don’t see any indication why the connection was dropped 2 times. The only thing I can think of is that normally HA gets rebooted when it gets an upgraded. Since watchtower is handling these upgrades, these happen for a lot of containers a once, resulting in a temporary high load of my server. Maybe the KNX IP Gateway is shutting down the connection due to a slow response or something?
I just manually restarted HA but the connection seems to remain stable (no reconnects).