Openhab / KNXnet/IP Tunneling-Problem führt zum Absturz der DiskStation

[Apple Jack]

Hallo,

das ist mein erster eigener Beitrag hier - hoffe, dass ich alles richtig mache.

Bislang konnte ich meine Probleme immer durch Suchen lösen. Jetzt bin ich aber verzweifelt und hoffe, hier einen Lösungsansatz zu finden.

Ich nutze:

• openhab 2.4
• Synology DS 216+II / DSM 6.22
• KNX Binding 1 (tunneling mode über Siemens IF 148/22)
• ZWave-Binding 2
• weitere in diesem Zusammenhang unauffällige Bindings

Ich hatte in den letzten 2 Jahren keinerlei Probleme mit meiner KNX-Konfiguraion. Vor drei Wochen habe ich nach einem Systemstart aber diverse Fehler in den Log-Dateien. Ich finde die Ursache nicht, zumal ich auch keine (direkten) Änderungen vorgenommen.

Ich habe zwischenzeitlich den Switch gegen einen größeren getauscht und ein ZWave-Device, mit dem ich Probleme hatte, neu inkludiert.Ob hier ein Zusammenhang besteht weiß ich nicht, da die Probleme erst zeitlich später auftraten.

Problembeschreibung:
Nach dem Neustarten läuft das System trotz einiger Fehlermeldungen (siehe unten) zunächst einwandfrei. Nach eingen Stunden (oder wenigen Tagen) stürzt meine Diskstation ab und ist nicht mehr erreichbar oder ich bekomme einen riesigen Traffic auf den Bus und hunderte Ein/Aus-Befehle verwandeln Haus und Garten in eine ungewollte Discobeleuchtung.

Was ich bislang unternommen habe:

• cache und tmp gelöscht
• openHAB deinstalliert und neu aufgesetzt
• rules-Datei vorübergehend minimiert

Fehlermeldungen:

2019-09-22 12:08:22.428 [WARN ] [tuwien.auto.calimero                ] - KNXnet/IP Tunneling 192.168.178.47:3671: received service acknowledgment with wrong send sequence 26, expected 27 - ignored
2019-09-22 12:08:30.430 [WARN ] [tuwien.auto.calimero                ] - KNXnet/IP Tunneling 192.168.178.47:3671: received service acknowledgment with wrong send sequence 214, expected 215 - ignored
2019-09-22 12:08:35.519 [WARN ] [tuwien.auto.calimero                ] - KNXnet/IP Tunneling 192.168.178.47:3671: received service acknowledgment with wrong send sequence 5, expected 6 - ignored
2019-09-22 12:09:16.725 [WARN ] [.binding.knx.internal.bus.KNXBinding] - Value 'OFF' could not be sent to the KNX bus using datapoint 'command DP 0/0/16 garten_li_alle, DPT main 0 id 1.001, low priority' - retrying one time: no confirmation reply received for L-Data.req from 0.0.0 to 0/0/16, low priority hop count 6 repeat tpdu 00 80
2019-09-22 12:09:16.758 [WARN ] [tuwien.auto.calimero                ] - KNXnet/IP Tunneling 192.168.178.47:3671: response timeout waiting for confirmation
tuwien.auto.calimero.exception.KNXTimeoutException: no confirmation reply received for L-Data.req from 0.0.0 to 0/0/16, low priority hop count 6 repeat tpdu 00 80
    at tuwien.auto.calimero.knxnetip.ClientConnection.doExtraBlockingModes(ClientConnection.java:236) ~[?:?]
    at tuwien.auto.calimero.knxnetip.ConnectionBase.send(ConnectionBase.java:269) ~[?:?]
    at tuwien.auto.calimero.knxnetip.KNXnetIPTunnel.send(KNXnetIPTunnel.java:149) ~[?:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.onSend(KNXNetworkLinkIP.java:263) ~[?:?]
    at tuwien.auto.calimero.link.AbstractLink.send(AbstractLink.java:304) ~[?:?]
    at tuwien.auto.calimero.link.KNXNetworkLinkIP.sendRequestWait(KNXNetworkLinkIP.java:240) ~[?:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:466) ~[?:?]
    at tuwien.auto.calimero.process.ProcessCommunicatorImpl.write(ProcessCommunicatorImpl.java:438) ~[?:?]
    at org.openhab.binding.knx.internal.bus.KNXBinding.writeToKNX(KNXBinding.java:149) ~[?:?]
    at org.openhab.binding.knx.internal.bus.KNXBinding.internalReceiveUpdate(KNXBinding.java:126) ~[?:?]
    at org.openhab.core.binding.AbstractBinding.receiveUpdate(AbstractBinding.java:113) ~[?:?]
    at org.openhab.core.events.AbstractEventSubscriber.handleEvent(AbstractEventSubscriber.java:39) ~[?:?]
    at org.apache.felix.eventadmin.impl.handler.EventHandlerProxy.sendEvent(EventHandlerProxy.java:415) ~[?:?]
    at org.apache.felix.eventadmin.impl.tasks.HandlerTask.runWithoutBlacklistTiming(HandlerTask.java:82) ~[?:?]
    at org.apache.felix.eventadmin.impl.tasks.SyncDeliverTasks.execute(SyncDeliverTasks.java:104) ~[?:?]
    at org.apache.felix.eventadmin.impl.tasks.AsyncDeliverTasks$TaskExecuter.run(AsyncDeliverTasks.java:166) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:?]
    at java.lang.Thread.run(Thread.java:748) ~[?:?]
2019-09-22 12:11:14.170 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@4430ec99' takes more than 5000ms.
2019-09-22 12:12:30.793 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.core.thing.internal.CommunicationManager@49910606' takes more than 5000ms.
2019-09-22 12:37:40.351 [INFO ] [veClimateControlScheduleCommandClass] - NODE 3 reported: Override type: NO_OVERRIDE, ScheduleState: [UNUSED]
2019-09-22 12:41:24.026 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 17d954e9-7c3e-430f-9b99-9f9fd8d2e2ed, base URL = http://localhost:8080)
2019-09-22 12:41:24.029 [WARN ] [nx.internal.connection.KNXConnection] - KNX link has been lost (reason: server request on object tunneling link link (closed) 192.168.178.47:3671 TP1 medium, device 0.0.0, hopcount 6)
2019-09-22 12:41:30.783 [ERROR] [.binding.knx.internal.bus.KNXBinding] - Received detach Event.

Oder weitere Fehlermeldungen wie diese:

start.png
Hat jemand eine Idee woran mein Fehler liegt und kann mir helfen?

Danke vorab!!!

Grüße
Apple Jack

[Apple Jack]

Inzwischen habe ich folgendes ohne Erfolg getestet:

• Switch zurück getauscht
• Ältere Item-, Rules- und Sitemap-Datei geladen

Daran hat es nicht gelegen. Auch läuft die DiskStation ohne openHAB stabil.

Überelege, ob es ein Hardware-Probleme des KNX-Gateways sein könnte...?

[Apple Jack]

Ich bin immernoch verzweifelt. Mir kann offensichtlich keiner helfen!?

Das Problem ist noch schlimmer geworden. Meine Synology stürzt gefühlt immer häufiger ab.

Aber nur wenn openHAB läuft.

Sehr merkwürdig ist, dass die letzten Stunden vor dem Systemabsturz in den Log-Dateien fehlen! Auch Einträge, die ich vorher gesehen habe sind weg.

Weiß einer woran das liegt?

Noch eine andere Frage: Ich habe permanent eine hohe RAM-Auslastung durch openHAB (ca. 200 bis 350 MB). Das hatte ich vorher nie geprüft.

Ist das normal?

Unabhängig davon werde ich den Arbeitsspeicher mal erweitern. Wollte ich mal machen.

Wenn irgend einer eine (andere) Idee hat, oder meine Fragen beantworten könnte, ich wäre ihm sehr, sehr dankbar...

Grüße Apple Jack

[udo1toni]

Im Zweifel wäre der erste Versuch, openHAB mal komplett zu deinstallieren und neu zu installieren.

[Apple Jack]

Hallo und Danke für den Hinweis!

Das De- und Neuinstallieren habe ich schon vorgenommen. Leider ohne Erfolg...

[thoern]

Also ich würde dem openHAB ja eine eigene HW spendieren. Ich halte wenig davon, so etwas auf vom Hersteller vorkonfigurierten Routern, Diskstations etc. mitlaufen zu lassen. Ich kann dir Shuttle-PC empfehlen. Einige davon sind auch für 24 x 7 Betrieb zertifiziert.

[HSorgYves]

thoern Was spricht denn gegen die Diskstation? Die läuft doch eh...

[Apple Jack]

Danke für den Vorschlag, thoern. Eigentlich würde ich aber in der bestehenden Lösung bleiben und die DS als Trägersystem behalten wollen. Bei mir hat das ja über 2 Jahre gut funktioniert und ich weiß auch, dass es bei vielen anderen ohne Probleme läuft.

VG Apple Jack

[Tom0101]

Also ich finde auch, dass das eine ideale Kombination ist um eine weitere Hardware einzusparen. Bei mir läuft Openhab 2.4 auf einer Synology DS115j (also das kleinste Modell das es gibt) eigentlich völlig problemlos, bis auf ein Problem das sich alle 2-3 Wochen zeigt und ich bisher nicht eingrenzen konnte. Das KNX Binding 2 hängt sich sporadisch auf und kann nur durch manuellen Eingriff wieder zum Leben erweckt werden.
Also nicht die Synology stürzt ab sondern nur das KNX Binding.
Auf der Synology läuft nichts außer Opnehab, ich nutze die NAS nur als Backup Laufwerk für meinen PC.

Ich habe mir jetzt zu Testzwecken einen Raspi bestellt und werde Openhab testweise jetzt mal eine Weile darauf auslagern, nur um zu sehen ob das Verhalten auf einer anderen Hardware auch so ist. Wenn ja dann kann ich die Synology als Problem Ursache ausschließen, denn ich will eigentlich langfristig dabei bleiben.


Du schreibst, nach einem Systemstart haben die Probleme angefangen.

Hast du eine USV an der Synology?
Ich musste im Frühjahr nach einem Gewitter feststellen dass die Synology nach einem kurzen Spannungsausfall stehen geblieben war. Nach dem manuellen Neustart war Openhab komplett weg, nichts ging mehr. Nur eine Neuinstallation hat geholfen, dabei bin ich dann auch auf die Version 2.4 umgestiegen.
Und seither habe ich eine USV an der Synology.

[Apple Jack]

Ich habe offenbar die Lösung gefunden!

Vor zwei Tagen habe ich den RAM von 1 auf 8 GB erweitert und siehe da: Alles läuft rund. Ich bin darauf gekommen, weil ein anderer User eine ähnliche ZWAVE-Fehlermeldung bekommen hat wie ich (siehe nachstehend) und ihm der Hinweis auf eine mögliche Systemüberlastung gegeben wurde.

[ERROR] [WaveSerialHandler$ZWaveReceiveThread] - Exception during ZWave thread.
java.lang.IllegalStateException: Queue full

Und auch bei meinen KNX-Fehlermeldungen hatte ich häufiger den Log-Eintrag

...takes more than 5000ms....

Ich weiß nicht, ob man eine DS115j erweitern kann. Das lässt sich aber bestimmt recht schnell rausfinden. Falls nicht, ist ein Raspi sicher eine Lösung.

Bei mir waren es sehr gut investierte 40,- Euro. Das Einbauen ist kinderleicht und der Effekt ist an allen Ecken zu spüren.

Etwas überrascht bin ich, dass im Ressourcen-Manager openHAB inzwischen regelmäßig über 800 MB Arbeitsspeicher in Anspruch nimmt. Dieser "Hunger" war mir nicht bewußt und hatte ich vorher auch nie getrackt gehabt. Erklärt aber einiges. Ich weiß nicht, ob openHAB von Haus aus so eine Auslastung hat oder, ob meine inzwischen immer umfangreicher gewordene Konfigutation dafür verantwortlich ist. Weiß das einer? Wie ist es bei Dir TOM0101?

Ich vermute, dass mein ZWAVE-Binding etwas anspruchsvoll ist. Meine Log-Dateien expodieren alle mit unnützen Infos. Falls die Anzahl der Einträge nur ansatzweise mit dem Ressourcen-Hunger korreliert, wäre das so. Unabhängig davon muss ich die Flut an Log-Einträgen eindämmen. Weiß aber noch nicht, wie das geht...

VG Apple Jack

[udo1toni]

Ein solcher Bedarf an Speicher ist eher ungewöhnlich, aber ein Stück weit kommt es sicher auf die verwendeten Addons an. typisch sollte openHAB unter 350MByte benötigen. Allerdings muss man aufpassen, denn wenn viel Ram zur Verfügung steht, wird die Garbage Collection von Java auch erst später aufräumen. Es kann also sein, dass Unmengen Speicher belegt erscheinen, obwohl sie in Wirklichkeit nur noch nicht entsorgt wurden (auch das Aufräumen kostet ja Zeit).

Beim Logging kommt es darauf an, was Du da alles zu Gesicht bekommst (ich habe kein ZWave). Du kannst über die Karaf Konsole das Logging zur Laufzeit beeinflussen. Im Zweifel stellst Du es einfach von INFO auf WARN. Ich habe kein zwave, deshalb zeige ich hier, wie es für knx geht. Du musst nur das grep nach zwave suchen lassen:

openhab@openhab2:~$ [COLOR=#B22222]openhab-cli console[/COLOR]

Logging in as openhab

                          __  _____    ____
  ____  ____  ___  ____  / / / /   |  / __ )
 / __ \/ __ \/ _ \/ __ \/ /_/ / /| | / __  |
/ /_/ / /_/ /  __/ / / / __  / ___ |/ /_/ /
\____/ .___/\___/_/ /_/_/ /_/_/  |_/_____/
    /_/                        2.5.0-SNAPSHOT
                               Build #1502

Hit '<tab>' for a list of available commands
and '[cmd] --help' for help on a specific command.
Hit '<ctrl-d>' or type 'system:shutdown' or 'logout' to shutdown openHAB.

openhab> [COLOR=#B22222]bundle:list -s | grep[/COLOR] [COLOR=#FF0000]knx[/COLOR]                                      <---- zwave statt knx suchen
246 x Active   x  80 x 2.5.0.201901142229     x [COLOR=#008000]org.openhab.binding.knx[/COLOR] <---- Suchergebnis
openhab> [COLOR=#B22222]log:set WARN[/COLOR] [COLOR=#008000]org.openhab.binding.knx[/COLOR]                           <---- Suchergebnis einsetzen
openhab> [COLOR=#B22222]log:list[/COLOR]
Logger                                             │ Level
───────────────────────────────────────────────────┼──────
ROOT                                               │ WARN
javax.jmdns                                        │ ERROR
org.apache.karaf.jaas.modules.audit                │ INFO
org.apache.karaf.kar.internal.KarServiceImpl       │ ERROR
org.apache.karaf.shell.support                     │ OFF
org.apache.sshd                                    │ WARN
org.eclipse.lsp4j                                  │ OFF
org.eclipse.smarthome                              │ INFO
org.jupnp                                          │ ERROR
org.openhab                                        │ INFO
[COLOR=#0000FF]org.openhab.binding.knx                            │ WARN[/COLOR]               <---- Loglevel ist gesetzt
org.ops4j.pax.url.mvn.internal.AetherBasedResolver │ ERROR
org.ops4j.pax.web.pax-web-runtime                  │ OFF
smarthome.event                                    │ INFO
smarthome.event.InboxUpdatedEvent                  │ ERROR
smarthome.event.ItemAddedEvent                     │ ERROR
smarthome.event.ItemRemovedEvent                   │ ERROR
smarthome.event.ItemStateEvent                     │ ERROR
smarthome.event.ThingAddedEvent                    │ ERROR
smarthome.event.ThingRemovedEvent                  │ ERROR
smarthome.event.ThingStatusInfoEvent               │ ERROR
openhab>[COLOR=#B22222]logout[/COLOR]

openhab@openhab2:~$

[Apple Jack]

udo1toni

Klasse, das hilft mir weiter. Danke!

Damit kann ich meine Log-Datei etwas übersichtlicher halten. Jetzt habe ich nur noch das Problem, dass meine Events-Logs vor allem von dem Z-Wave-Stick (Controller) gespamt wird. Dafür hast Du nicht evtl. auch noch eine Idee parat?

2019-10-12 14:02:24.813 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:293ebf14:node4' has been updated.
2019-10-12 14:02:24.814 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12804 to 12805
2019-10-12 14:02:25.814 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_ack changed from 2076 to 2077
2019-10-12 14:02:25.820 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12805 to 12806
2019-10-12 14:02:25.837 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12806 to 12807
2019-10-12 14:02:42.179 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12807 to 12808
2019-10-12 14:02:42.653 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12808 to 12809
2019-10-12 14:02:42.674 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12809 to 12810
2019-10-12 14:02:42.694 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12810 to 12811
2019-10-12 14:02:42.716 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12811 to 12812
2019-10-12 14:02:43.737 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_ack changed from 2077 to 2078
2019-10-12 14:02:43.744 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12813 to 12814
2019-10-12 14:02:43.760 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12814 to 12815
2019-10-12 14:02:52.302 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12815 to 12816
2019-10-12 14:02:52.324 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12816 to 12817
2019-10-12 14:02:52.344 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12817 to 12818
2019-10-12 14:02:52.370 [vent.ItemStateChangedEvent] - zwave_serial_zstick_293ebf14_serial_sof changed from 12818 to 12819

Mit dem Arbeitsspeicher scheint das in der Tat so zu sein wie Du sagst. Zumal mein openHAB inzwischen über 1,2 GB in Anspruch nimmt. Leicht beunruhigend ist das schon...

[Tom0101]

Etwas überrascht bin ich, dass im Ressourcen-Manager openHAB inzwischen regelmäßig über 800 MB Arbeitsspeicher in Anspruch nimmt. Dieser "Hunger" war mir nicht bewußt und hatte ich vorher auch nie getrackt gehabt. Erklärt aber einiges. Ich weiß nicht, ob openHAB von Haus aus so eine Auslastung hat oder, ob meine inzwischen immer umfangreicher gewordene Konfigutation dafür verantwortlich ist. Weiß das einer? Wie ist es bei Dir TOM0101?

Also die DS115J hat 256MB Arbeitsspeicher und kann nicht erweitert werden. Das ist mir schon klar dass diese Hardware eigentlich nicht performant genug ist, dennoch läuft das System relativ stabil. Die Ausalstung, es läuft nur Openhab:

Syno_ram.JPG

[Apple Jack]

Tom0101 101

So sah es bei mir auch aus. Der RAM war bei ca. 80% Auslastung. Man könnte meinen, dass die 20% Puffer ausreichen sollten. Aber bei mir taten sie das nicht. Und ich hatte 1 GB RAM - allerdings noch diverse andere Programme am Start.

Unter Prozesse siehst Du die Nutzlast von openHAB. Vermutlich wird Sie speicherbedingt gedeckelt bzw. gedrosselt. Auf jeden Fall ist das Ausweichen auf einen Raspi bei Dir eine sinnvolle Überlegung.

[udo1toni]

Bei 256MByte RAM ist eine andere Plattform auf jeden Fall sinnvoll.
Wenn Du eh neu kaufst, nimm den RPi4 mit 2 oder 4 GByte, der kostet nicht die Welt im Vergleich zur 1GByte Variante, aber Du hast jede Menge Reserven für was auch immer (notfalls um das NAS damit zu ersetzen - mit USB3 und GBit-Ethernet geht da Einiges...)