FHEM hängt beim Booten, wenn KNX-IP Gateway offline ist

Begonnen von docm, 15 Oktober 2017, 14:39:22

Vorheriges Thema - Nächstes Thema

docm

Hallo,
ich bin neu im Forum und arbeite mich gerade in FHEM ein. Mein Neubau soll ein KNX-System erhalten. Einige Komfort-Funktionen (Witterungsführung der Raffstores etc.) möchte ich über FHEM steuern. Es ist super, dass es hier so rege Kommunikation im Forum gibt und ich freue mich auf den Austausch. Hoffentlich kann mir jemand bei folgendem Problem helfen.

Meine Konfiguration:
Weinzierl 731 KNX Interface (Tunneling Mode)
Per Ethernet über Router verbunden mit raspi 3 (Jessie), alle IP-Adressen per DHCP vergeben
knxd als systemd Dämon mit KNXD_OPTS="-e 0.0.1 -E 0.0.2:8 -c -b ipt:KNX_IP_Interface_731"
FHEM läuft auf dem selben raspi
Definition des I/O Devices als TUL

define myTUL TUL knxd:localhost 0.0.20

Im Normalfall funktioniert alles, d.h. FHEM empfängt und sendet alle gewünschten Gruppenadressen.

Wenn beim Booten des raspi das KNX IP Gateway offline ist, bzw. keine NW-Verbindung dahin besteht, läuft knxd in einen Fehler und startet alle 10 sec neu. Im syslog werden entsprechende Meldungen protokolliert.

Oct 15 14:11:07 raspberrypi systemd[1]: knxd.service: Service hold-off time over, scheduling restart.
Oct 15 14:11:07 raspberrypi systemd[1]: Stopped KNX Daemon.
Oct 15 14:11:07 raspberrypi systemd[1]: Starting KNX Daemon...
Oct 15 14:11:07 raspberrypi knxd[1153]: initialisation of backend 'ipt:KNX_IP_Interface_731' failed
Oct 15 14:11:07 raspberrypi systemd[1]: knxd.service: Main process exited, code=exited, status=1/FAILURE
Oct 15 14:11:07 raspberrypi systemd[1]: Failed to start KNX Daemon.
Oct 15 14:11:07 raspberrypi systemd[1]: knxd.service: Unit entered failed state.
Oct 15 14:11:07 raspberrypi systemd[1]: knxd.service: Failed with result 'exit-code'.

So weit ok und erwartetes Verhalten.

Jetzt das Problem:
In besagter Situation (IP Gateway offline) bleibt FHEM reproduzierbar beim Hochfahren im define myTUL hängen.
Abhilfe: Während FHEM hängt, manuelles Stoppen des knxd über die Linux Shell

$sudo systemctl stop knxd
$sudo systemctl stop knxd.service

Daraufhin läuft FHEM fertig hoch, legt aber das Device myTUL nicht an.
Über rereadcfg im Webinterface kann ich die config neu laden, diesmal läuft es auch durch, myTUL wird angelegt im STATE "disconnected". Dieses Verhalten hätte ich mir gleich beim Hochfahren gewünscht. Es ist sehr lästig, manuell eingreifen zu müssen. Schließlich will ich mit FHEM auch die Funktion des knx Systems überwachen.

Nun hoffe ich auf Unterstützung durch das Forum. Habe ich etwas falsch konfiguriert? Oder gibt es im Modul TUL möglicherweise einen Bug? Konnte jemand das beschriebene Verhalten bei sich beobachten.

Viele Grüße


Andi291

Servus!

Was sagt denn das Log dazu? Schalt mal Level 5 an der TUL ein, bitte...

docm

Hallo Andi,
danke für deine schnelle Antwort.
Da FHEM ja schon im define des TUL hängen bleibt, wird ein nachfolgendes attrib nicht mehr ausgeführt. Also werde ich wohl mal global verbose auf 5 stellen müssen. Melde mich, sobald ich ein Resultat habe.

Viele Grüße

docm

So,
ich habe jetzt direkt vor dem define in der fhem.cfg vergose global auf 5 gesetzt und anschließend zurück auf 3.
Hier der entsprechende Ausschnitt aus der fhem.cfg

# TUL starten mit verbose 5
attr global verbose 5
define myTUL TUL knxd:localhost 0.0.20
attr myTUL room KNX
# verbose auf 3 zurücksetzen


Und hier die entsprechenden Log-Ausgaben. Um 19:51:44 hatte ich dann manuell den knxd gestoppt, damit FHEM weiter lief.

2017.10.15 19:50:14 5: Cmd: >define myTUL TUL knxd:localhost 0.0.20<
2017.10.15 19:50:14 5: Loading ./FHEM/00_TUL.pm
2017.10.15 19:50:14 0: Using EIB is deprecated. Please migrate to KNX soon. Module 10_EIB is not maintained any longer. If you still want to use the module EIB,
please set the attribute useEIB to 1 within the tul-device. Please keep in mind, that 10_KNX has a changed syntax regarding the definition, arguments and readings. Please refer to the commandref.
As well 10_EIB and 10_KNX are compatible to daemon eibd and knxd.
2017.10.15 19:50:14 3: TUL opening myTUL device knxd:localhost
2017.10.15 19:50:14 3: TUL device opened
2017.10.15 19:50:14 5: sendRequest: 0026000000

eibd communication failed
openGroupSocket failed
2017.10.15 19:51:44 1: Cannot init knxd:localhost, ignoring it
2017.10.15 19:51:44 1: define myTUL TUL knxd:localhost 0.0.20: 1
2017.10.15 19:51:44 5: Cmd: >attr myTUL room KNX<
2017.10.15 19:51:44 5: Cmd: >attr global verbose 3<

Viel steht ja nicht drin.
Hat das Problem möglicherweise mit der Zweiteiligkeit des knxd / knxd.socket zu tun? Es könnte durchaus sein, dass fhem die Socket-Verbindung öffnen kann, dann aber funktioniert der sendRequest nicht. Vielleicht blockiert fhem hier?? Wenn ich den Dämon stoppe, geht der Socket hops, fhem kriegt das mit und macht mit Fehlermeldung weiter...

Viele Grüße

Andi291


docm

Hallo Andi291,

ich habe mal etwas in den Perl-Code des TUL geschaut. In TUL_OpenDev() wird der Socket in Zeile 474 ohne Fehler geöffnet. Das Programm setzt sich in TUL_DoInit() fort. Dieses ruft in Zeile 182 openGroupSocket() auf.

Hier wird zunächst ein sendRequest() über den Socket geschickt (Zeile 917) und anschließend mit getRequest() auf eine Antwort gewartet. getRequest() nutzt sysread() um vom Socket zu lesen (Zeile 1109) und blockiert hier, da keine Antwort kommt. sysread() wartet mindestens auf das erste Zeichen, bzw EOF.
Das EOF kommt erst dann, wenn ich den knxd manuell stoppe.

Der Code müsste so abgeändert werden, dass sysread() mit einem Timeout versehen wird. Wenn keine Daten kommen, sollte das Device nicht geschlossen werden, sondern in den Zustand disconnected gehen. Dann könnte z.B. alle 60 Sekunden erneut versucht werden, den KNX zu erreichen.

Ich bin nicht fit genug in Perl, aber du kriegst das gewiss umgesetzt. Wäre super!
Viele Grüße


docm


Andi291

Probier mal die beiden Varianten.

Betroffene Zeile:
my $conn = IO::Socket::INET->new(PeerAddr => $host, PeerPort => $port,Proto => 'tcp');

Variante 1:
my $conn = IO::Socket::INET->new(
PeerAddr => $host,
PeerPort => $port,
Proto => 'tcp,'
Timeout => 60
);


Variante 2:
my $conn = IO::Socket::INET->new(PeerAddr => $host, PeerPort => $port,Proto => 'tcp');
IO::Socket::Timeout->enable_timeouts_on($conn);
$conn->write_timeout(60);

docm

Hallo Andi,
ich kann es erst am Mittwoch testen. Melde mich dann wieder.
Vielen Dank!

Andreas

docm

Hallo Andi,
danke für deine Tipps. Leider haben beide Varianten nicht funktioniert.
Der Hinweis auf IO::Socket::Timeout ist aber sehr nützlich.

Um diese Klasse nutzen zu können, musste ich auf meinem Raspberry zunächst das notwendige Package installieren

sudo apt-get install libio-socket-timeout-perl


Der Aufhänger geschieht beim Lesen vom Socket, daher muss auch ein Read Timeout gesetzt werden.
Folgendes Codefragment führt dazu, dass FHEM nach Ablauf des Timeouts weitermacht, also nicht mehr hängen bleibt.

my $conn = IO::Socket::INET->new(PeerAddr => $host, PeerPort => $port,Proto => 'tcp');
if($conn)
{
delete($hash->{NEXT_OPEN})
}
else
{
Log3 ($name, 3, "Can't connect to $dev: $!") if(!$reopen);
$readyfnlist{"$name.$dev"} = $hash;
$hash->{STATE} = "disconnected";
$hash->{NEXT_OPEN} = time()+60;
return "";
}
use IO::Socket::Timeout;
IO::Socket::Timeout->enable_timeouts_on($conn);
$conn->write_timeout(60);
$conn->read_timeout(60);



Leider sind wir damit noch nicht am Ziel. Der Timeout lässt die Initialisierung des TUL abbrechen. Damit finden die nachfolgend definierten KNX Devices kein IO Device vor.
Selbst wenn der knx Bus später wieder online ist, bleiben die KNX Devices ohne IO Device.

Siehe Ausschnitt aus dem FHEM Log

2017.11.04 22:12:59 3: TUL opening myTUL device knxd:localhost
2017.11.04 22:12:59 3: TUL device opened
2017.11.04 22:12:59 5: sendRequest: 0026000000

eibd communication failed
openGroupSocket failed
2017.11.04 22:14:12 1: Cannot init knxd:localhost, ignoring it
2017.11.04 22:14:12 1: define myTUL TUL knxd:localhost 0.0.20: 1
2017.11.04 22:14:14 3: No I/O device found for timedev
2017.11.04 22:14:14 3: No I/O device found for Wohnzimmer.Esstisch
2017.11.04 22:14:14 3: No I/O device found for Wohnzimmer.Deckenleuchte
2017.11.04 22:14:14 3: No I/O device found for Wohnzimmer.Temperatur
2017.11.04 22:14:14 3: No I/O device found for EsIstTag


Fällt dir hiezu noch etwas ein?
Viele Grüße
Andreas

Andi291

Man müsste den Timeout "abfangen" und die TUL in den State Disconnected versetzen aber nicht löschen.
Das müsste hinhauen...

Blöd ist die Gschichte mit der zusätzlichen Perl-Lib. Das macht dem Standarduser Probleme...

docm

Alternativ kommt man vielleicht mit IO::Select ans Ziel. Die Methode can_read(timeout) sollte anzeigen, ob Daten am Socket zum lesen vorhanden sind.
Diese Klasse ist Bestandteil von perl-base.
Werde es mir mal anschauen.

Andi291

DAS ist ne gute Idee. Hab ich unter Java mal was gemacht...

docm

Hallo,

anbei die modifizierte Variante des TUL Codes. Änderungen sind im Source dokumentiert. Ich habe es auf meinem System jetzt eine Zeitlang erfolgreich getestet (knxd auf localhost mit Weinzierl 731 angebunden über IP). Ob es mit dem Original TUL Stick auch funktioniert, müsste jemand testen. Ich habe keinen.

Viele Grüße

CoolTux

Ich kenne den Code nicht, kann also komplett schief liegen.
Aber wenn ihr einen Socket auf macht, warum schiebt Ihr ihn nicht ins FHEM select. Dann kümmert sich FHEM in der Hauptschleife darum ob Daten zum abholen Anliegen oder nicht. Wenn eine Socketverbindung nicht aufgebaut werden kann kann man dafür sorgen das dies nach x Minuten noch einmal probiert wird.



Grüße
Du musst nicht wissen wie es geht! Du musst nur wissen wo es steht, wie es geht.
Support me to buy new test hardware for development: https://www.paypal.com/paypalme/MOldenburg
My FHEM Git: https://git.cooltux.net/FHEM/
Das TuxNet Wiki:
https://www.cooltux.net