calimero-project / calimero-core

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

Warnings from Calimero #106

Closed Pirx99 closed 2 years ago

Pirx99 commented 2 years ago

Can someone help me to understand warnings coming from Calimero.knxnetip? I'm using a KNX binding within OpenHAB 3.2. The connection to my KNXnet/IP Router (made by Enertex) seems to work in general. However upon startup of OpenHab and after first connection to the KNX Binding I see in the log file thousands of those messages: 2021-12-30 22:45:07.422 [WARN ] [p.KNXnet/IP Routing 224.0.23.12:3671] - received invalid frame tuwien.auto.calimero.KNXFormatException: wrong size for routing busy indication: 0x4 at tuwien.auto.calimero.knxnetip.servicetype.RoutingBusy.<init>(RoutingBusy.java:84) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting.handleServiceType(KNXnetIPRouting.java:463) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ConnectionBase.handleServiceType(ConnectionBase.java:373) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ReceiverLoop.onReceive(ReceiverLoop.java:93) [bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting$ChannelReceiver.receive(KNXnetIPRouting.java:438) [bundleFile:?] at tuwien.auto.calimero.internal.UdpSocketLooper.loop(UdpSocketLooper.java:134) [bundleFile:?] at tuwien.auto.calimero.knxnetip.ReceiverLoop.run(ReceiverLoop.java:75) [bundleFile:?] at java.lang.Thread.run(Thread.java:829) [?:?] 2021-12-30 22:45:07.423 [WARN ] [p.KNXnet/IP Routing 224.0.23.12:3671] - received invalid frame tuwien.auto.calimero.KNXFormatException: wrong size for routing busy indication: 0x4 at tuwien.auto.calimero.knxnetip.servicetype.RoutingBusy.<init>(RoutingBusy.java:84) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting.handleServiceType(KNXnetIPRouting.java:463) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ConnectionBase.handleServiceType(ConnectionBase.java:373) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ReceiverLoop.onReceive(ReceiverLoop.java:93) [bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting$ChannelReceiver.receive(KNXnetIPRouting.java:438) [bundleFile:?] at tuwien.auto.calimero.internal.UdpSocketLooper.loop(UdpSocketLooper.java:134) [bundleFile:?] at tuwien.auto.calimero.knxnetip.ReceiverLoop.run(ReceiverLoop.java:75) [bundleFile:?] at java.lang.Thread.run(Thread.java:829) [?:?] 2021-12-30 22:45:07.424 [WARN ] [p.KNXnet/IP Routing 224.0.23.12:3671] - received invalid frame tuwien.auto.calimero.KNXFormatException: wrong size for routing busy indication: 0x4 at tuwien.auto.calimero.knxnetip.servicetype.RoutingBusy.<init>(RoutingBusy.java:84) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting.handleServiceType(KNXnetIPRouting.java:463) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ConnectionBase.handleServiceType(ConnectionBase.java:373) ~[bundleFile:?] at tuwien.auto.calimero.knxnetip.ReceiverLoop.onReceive(ReceiverLoop.java:93) [bundleFile:?] at tuwien.auto.calimero.knxnetip.KNXnetIPRouting$ChannelReceiver.receive(KNXnetIPRouting.java:438) [bundleFile:?] at tuwien.auto.calimero.internal.UdpSocketLooper.loop(UdpSocketLooper.java:134) [bundleFile:?]

What do they mean? Do I have problem on the binding side or on the Router? These warnings stop to after few hours. One problem stay: some KNX events are not getting forwarded to OpenHAB. I have no idea at the moment how to approach the problem.

bmalinowsky commented 2 years ago

If you really get thousands of warnings, it means that OpenHab is sending thousands of messages with insufficient time intervals between each to the router.

A routing busy structure is 6 bytes (12 w/ header), not 4.

J-N-K commented 2 years ago

The stack trace does not indicate any openHAB induced action and to my knowledge "Routing Busy" is nothing that openHAB creates on its own. Could this be the result of a lot of GroupValueRead requests (IIRC there is no rate-limiting for requests on startup). That would explain why the router is busy, but not why the structure is 4 and not 6 bytes long.

Pirx99 commented 2 years ago

Thanks J-N-K. I don't have any GroupValueRead requests and I dropped every interval settings for the Things. So there is nothing I could think, that I could influanced this mass of warnings. This is my KNX-binding definition: Bridge knx:ip:bridge "KNX IP Interface" [ type="ROUTER", readingPause=50, responseTimeout=10, readRetriesLimit=3, autoReconnectPeriod=60 ] { Thing device KG_Gira2174_Dimmaktor1 "GIRA 4-fach Dimmaktor1" // [address="1.1.4"] { ..........

Pirx99 commented 2 years ago

another question: who is sending the routing busy message? Is it the KNX router or OpenHab?

J-N-K commented 2 years ago

@bmalinowsky Do you think this could be caused by misconfigured multicast? IIRC there have been issues (with KNX routing in general) with some routers and switches with broken firmware.

@Pirx99 I would recommend to disable all physical addresses in your config, they are not necessary and the corresponding code is not working as designed IMO. But this is openHAB, not Calimero related.

Pirx99 commented 2 years ago

@J-N-K, I already disabled all physical addresses in my config. Unfortunately, it did not help.

To be honest, I've been struggling with this problem for a while, but I haven't had time to deal with it. It arose after I changed several components at once: upgrade from OH2 to OH3 with many related changes and the change from Fritz!Box to Telekom Speedport Pro Plus -> this could be where the MultiCast problem comes from, but there is no way to set anything.

Pirx99 commented 2 years ago

Additional info: I have just measured the number of MultiCast packets in my network with my Cisco switch. In about 60 seconds I've got (packets received):

bmalinowsky commented 2 years ago

@J-N-K broken firmware: wouldn't this affect all mcasts, to be observed all over the place? Of course it could be, one should probably cross-check with, e.g., a wshark trace.

@Pirx99 are those only KNX multicasts? If yes, then the message count is quite high and not realistic for a TP1 network. It's interesting that OpenHAB has ~1/2 the messages as the router. One explanation could be that for every message OpenHAB sends (and the router receives), the router is also sending a routing busy notification? But the vast amount of messages and the parsing error are two different issues. The message parser throws an exception simply because the message size is not correct. It's not causing those messages.

htttito commented 2 years ago

@Pirx99 Hallo Pirx99! I have read that you have a working Openhab integration of your Dimplex WPM with modbus?! Please can you help me with the files? .things .items

Pirx99 commented 2 years ago

@Pirx99 are those only KNX multicasts? ... YES!

@bmalinowsky, now I found time and pleasure and did a simple test: I replaced the Telekom Router (Speedport Pro Plus) by my old Fritz!Box DSL Router and .... everything work as desired. No more MultiCast problems. To me it looks like a broken firmware within the Telekom Router. I will contact Telekom support and most probably give this router back.

Many thanks for your help.

Update: I ordered a new Fritz!Box which fullfills my requirement and after a successful test with KNX I gonna close the issue.

Pirx99 commented 2 years ago

Hallo Pirx99! I have read that you have a working Openhab integration of your Dimplex WPM with modbus?! Please can you help me with the files? .things .items

@htttito Yes, I do Dimplex WPM with modbus.

dimplex.things

Bridge modbus:tcp:dimplex [ host="192.168.178.4", port=502, id=1 ] {

    Bridge poller p1 [ start=1, length=5, refresh=50000, type="holding" ] {
        Thing data AussenTemp [ readStart="1", readValueType="int16", readTransform="JS(divide_by_10.js)"]
        Thing data RuecklaufTemp [ readStart="2", readValueType="int16", readTransform="JS(divide_by_10.js)"]
        Thing data WarmwasserTemp [ readStart="3", readValueType="int16", readTransform="JS(divide_by_10.js)"]
        Thing data VorlaufTemp [ readStart="5", readValueType="int16", readTransform="JS(divide_by_10.js)"]
    }

    Bridge poller p2 [ start=5015, length=3, refresh=50000, type="holding" ] {
        Thing data Betriebsmodus [ readStart="5015", readValueType="uint16", writeStart="5015", writeValueType="uint16", writeType="holding" ]
        Thing data Partystunden [ readStart="5016", readValueType="uint16", writeStart="5016", writeValueType="uint16", writeType="holding" ]
        Thing data Urlaubstage [ readStart="5017", readValueType="uint16", writeStart="5017", writeValueType="uint16", writeType="holding" ]
    }

    Bridge poller p3 [ start=97, length=1, refresh=50000, type="holding" ] {
        Thing data PufferTemp [ readStart="97", readValueType="int16", readTransform="JS(divide_by_10.js)"]
    }

    Bridge poller p4 [ start=53, length=1, refresh=50000, type="holding" ] {
        Thing data RuecklaufSollTemp [ readStart="53", readValueType="int16", readTransform="JS(divide_by_10.js)"]
    }

    Bridge poller p5 [ start=103, length=3, refresh=50000, type="holding" ] {
        Thing data Status [ readStart="103", readValueType="uint16"]
        Thing data WPsperre [ readStart="104", readValueType="uint16"]
        Thing data Stoerung [ readStart="105", readValueType="uint16"]
    }

    Bridge poller p6 [ start=5045, length=3, refresh=50000, type="holding" ] {
        Thing data Hysterese [ readStart="5045", readValueType="uint16", writeStart="5045", writeValueType="uint16", writeType="holding" ]
        Thing data WarmwasserSollTemp [ readStart="5047", readValueType="uint16", writeStart="5047", writeValueType="uint16", writeType="holding" ]
    }

}

dimplex.items

Number Hzg_Betriebsmodus    "Betriebsmodus" <movecontrol>  {channel="modbus:data:dimplex:p2:Betriebsmodus:number" }

Number Hzg_Warmwasser_Temperatur    "Warmwasser-Temperatur [%.1f °C]" <temperature>  { channel="modbus:data:dimplex:p1:WarmwasserTemp:number" }

Number Hzg_Warmwasser_SOLL_Temp     "Warmwasser-SOLL-Temperatur [%.1f °C]" <temperature>  { channel="modbus:data:dimplex:p6:WarmwasserSollTemp:number" }

Number Hzg_Warmwasser_Hysterese     "Warmwasser Hysterese [%.1f K]" <temperature>  { channel="modbus:data:dimplex:p6:Hysterese:number" }

Number Hzg_Aussen_Temperatur        "Außentemperatur [%.1f °C]" <temperature>  { channel="modbus:data:dimplex:p1:AussenTemp:number" }

Number Hzg_Vorlauf_Temperatur       "Fussboden Vorlauf-Temperatur [%.1f °C]" <temperature> { channel="modbus:data:dimplex:p1:VorlaufTemp:number" }

Number Hzg_Ruecklauf_Temperatur     "Fussboden Rücklauf-Temperatur [%.1f °C]" <temperature> { channel="modbus:data:dimplex:p1:RuecklaufTemp:number" }

Number Hzg_Puffer_Temperatur            "Puffer-Temperatur [%.1f °C]" <temperature> (gDB_E5M)

Number Hzg_Puffer_Temperatur1           "Puffer-Temperatur1 [%.1f °C]" <temperature> (gDB_E5M) { channel="modbus:data:dimplex:p3:PufferTemp:number" }

Number Hzg_Ruecklauf_SollTemp       "Fussboden SOLL Rücklauf-Temperatur [%.1f °C]" <temperature> { channel="modbus:data:dimplex:p4:RuecklaufSollTemp:number" }
String Hzg_Status_TEXT              "Status [%s]" 

Number Hzg_Status_IN            { channel="modbus:data:dimplex:p5:Status:number" }

Number Hzg_Wsperre_IN           { channel="modbus:data:dimplex:p5:WPsperre:number" }

Number Hzg_Stoerung_IN          { channel="modbus:data:dimplex:p5:Stoerung:number" }

divide_by_10.js

(function(i) {
    return parseFloat(i) / 10;
 })(input)
htttito commented 2 years ago

@Pirx99 Wow thank you very very much!!! :-) Danke, Danke, Danke!!

Pirx99 commented 2 years ago

This error was caused by the firmware of Telekom Router Speedport Pro Plus. MultiCasting cannot be configured on that router. After replacing it with a Fritz!Box the issue disappeared.