search

calimero-project / calimero-core

Core library for KNX network access and management
Other
129 stars 65 forks source link

Dropping tunnelling connections #132

Open georgegougoudis opened 1 month ago

georgegougoudis commented 1 month ago

I've set up Calimero Server on a raspberry pi with a tpuart board conneced. My configuration is as following:

<?xml version="1.0" encoding="UTF-8"?>

<!-- Calimero server settings (required for startup) -->
<knxServer name="knx-server" friendlyName="KNX/IP Server">
    <!-- KNXnet/IP search & discovery -->
    <discovery listenNetIf="all" outgoingNetIf="all" activate="true" />

    <!-- Provides the KNXnet/IP-side configuration for access to one KNX subnet -->
    <serviceContainer activate="true" routing="true" networkMonitoring="true"
        udpPort="3671" listenNetIf="enu1u1">
        <knxAddress type="individual">1.1.0</knxAddress>
        <routing/>
        <disruptionBuffer expirationTimeout="30" udpPort="5555-5559" />
        <knxSubnet type="tpuart" medium="tp1">/dev/ttyAMA0</knxSubnet>
        <groupAddressFilter>
            <!-- <knxAddress type="group">2/1/1</knxAddress> -->
            <!-- <knxAddress type="group">2/1/0</knxAddress> -->
            <!-- <knxAddress type="group">2/1/20</knxAddress> -->
        </groupAddressFilter>

        <!-- Additional KNX individual addresses assigned to client KNXnet/IP connections (optional) -->
        <additionalAddresses>
            <knxAddress type="individual">1.1.240</knxAddress>
            <knxAddress type="individual">1.1.241</knxAddress>
            <knxAddress type="individual">1.1.242</knxAddress>
            <knxAddress type="individual">1.1.243</knxAddress>
            <knxAddress type="individual">1.1.244</knxAddress>
        </additionalAddresses>
    </serviceContainer>

</knxServer>

The tunneling connection drops and I get the following warnings:

12:03:23.131 [WARNING] io.calimero.server.knxnetip.KNX IP LinkLayer 192.168.1.117:54582: nonblocking send invoked while waiting for data response in state 2 - aborted
Exception in thread "KNX IP LinkLayer 192.168.1.117:54582 (TCP, channel 1, 1.1.240) sender" java.lang.IllegalStateException: waiting for data response
    at io.calimero.core/io.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:218)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.knxnetip.DataEndpoint.send(DataEndpoint.java:202)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.send(KnxServerGateway.java:1679)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.lambda$asyncSend$12(KnxServerGateway.java:1662)
    at java.base/java.lang.Thread.run(Unknown Source)
12:03:25.036 [WARNING] io.calimero.server.knxnetip.KNX IP LinkLayer 192.168.1.117:54582: nonblocking send invoked while waiting for data response in state 2 - aborted
Exception in thread "KNX IP LinkLayer 192.168.1.117:54582 (TCP, channel 1, 1.1.240) sender" java.lang.IllegalStateException: waiting for data response
    at io.calimero.core/io.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:218)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.knxnetip.DataEndpoint.send(DataEndpoint.java:202)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.send(KnxServerGateway.java:1679)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.lambda$asyncSend$12(KnxServerGateway.java:1662)
    at java.base/java.lang.Thread.run(Unknown Source)
12:03:25.384 [WARNING] io.calimero.server.knxnetip.KNX IP LinkLayer 192.168.1.100:44078: nonblocking send invoked while waiting for data response in state 2 - aborted
Exception in thread "KNX IP LinkLayer 192.168.1.100:44078 (TCP, channel 2, 1.1.241) sender" java.lang.IllegalStateException: waiting for data response
    at io.calimero.core/io.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:218)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.knxnetip.DataEndpoint.send(DataEndpoint.java:202)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.send(KnxServerGateway.java:1679)
    at io.calimero.server@3.0-SNAPSHOT/io.calimero.server.gateway.KnxServerGateway.lambda$asyncSend$12(KnxServerGateway.java:1662)
    at java.base/java.lang.Thread.run(Unknown Source)

It seems like this is happening in exactly 4 minutes intervals (like 4:02 more specifically) image

This is what my client device is reporting

2024-07-15 12:03:04.017 DEBUG (MainThread) [xknx.cemi] Incoming CEMI: <CEMIFrame code="L_DATA_IND" info="CEMIInfo("")" data="CEMILData(src_addr="IndividualAddress("1.1.6")" dst_addr="GroupAddress("6/2/6")" flags="1011110011010000" tpci="TDataGroup()" payload="<GroupValueWrite value="<DPTArray value="[0x36,0x34]" />" />")" />
2024-07-15 12:03:04.021 DEBUG (MainThread) [xknx.telegram] <Telegram direction="Incoming" source_address="1.1.6" destination_address="6/2/6" payload="<GroupValueWrite value="<DPTArray value="[0x36,0x34]" />" />" />
2024-07-15 12:03:04.850 DEBUG (KNX Interface) [xknx.log] Closing TCP transport. None
2024-07-15 12:03:04.860 DEBUG (MainThread) [xknx.state_updater] StateUpdater stopping
2024-07-15 12:03:07.862 DEBUG (KNX Interface) [xknx.log] Could not establish connection to KNX/IP interface. ConnectionRefusedError: [Errno 111] Connect call failed ('192.168.1.100', 3671)
2024-07-15 12:03:10.886 DEBUG (KNX Interface) [xknx.log] Could not establish connection to KNX/IP interface. ConnectionRefusedError: [Errno 111] Connect call failed ('192.168.1.100', 3671)
2024-07-15 12:03:13.920 DEBUG (KNX Interface) [xknx.knx] Sending to 192.168.1.100:3671/tcp: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECT_REQUEST" TotalLength="26" /> body="<ConnectRequest control_endpoint="0.0.0.0:0/tcp" data_endpoint="0.0.0.0:0/tcp" cri="<ConnectRequestInformation connection_type="TUNNEL_CONNECTION" knx_layer="DATA_LINK_LAYER" />" />" />
2024-07-15 12:03:14.062 DEBUG (KNX Interface) [xknx.raw_socket] Received via tcp: 06100206001402000802000000000000040411f1
2024-07-15 12:03:14.063 DEBUG (KNX Interface) [xknx.knx] Received from 192.168.1.100:3671/tcp: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="CONNECT_RESPONSE" TotalLength="20" /> body="<ConnectResponse communication_channel="2" status_code="ErrorCode.E_NO_ERROR" data_endpoint="0.0.0.0:0/tcp" crd="<ConnectResponseData request_type="ConnectRequestType.TUNNEL_CONNECTION" individual_address="1.1.241" />" />" />
2024-07-15 12:03:14.064 DEBUG (KNX Interface) [xknx.log] Tunnel established. communication_channel=2, address=1.1.241
2024-07-15 12:03:14.067 INFO (KNX Interface) [xknx.log] Successfully reconnected to KNX bus.
2024-07-15 12:03:14.082 DEBUG (KNX Interface) [xknx.knx] Sending to 192.168.1.100:3671/tcp: <KNXIPFrame <KNXIPHeader HeaderLength="6" ProtocolVersion="16" KNXIPServiceType="DESCRIPTION_REQUEST" TotalLength="14" /> body="<DescriptionRequest control_endpoint="0.0.0.0:0/tcp" />" />

Everytime the connection is dropped-reset. Any information to investigate this further would be greatly appreciated.

bmalinowsky commented 1 month ago

I think this is because of a recent change wrt the async response. The fix is on this branch, but unfortunately not yet in the server you are using.

bmalinowsky commented 1 month ago

The fix is now in the latest snapshot build.