DevIO UND readyfnlist Gemeinsame Anwendung so richtig ?

KölnSolar · 02 Februar 2018, 10:20:29

Liebe Experten,
ich kämpfe gerade erstmalig mit DevIO. Es wird in einem offiziellen Modul genutzt. Um Verhaltensweise von DevIO besser zu verstehen, habe ich dort ein paar Logs eingebaut.
Ich frage mich nun, ob DevIO für den Anwendungsfall so richtig implementiert ist und zum anderen verstehe ich das konkrete Verhalten in einem bestimmten Fall nicht.

Zuerst einmal die Frage nach der richtigen Implementierung. Bei dem Netzwerkgerät handelt es sich um einen Fernseher, der zum Zeitpunkt des defines im Netzwerk verfügbar sein kann oder auch nicht. Im laufenden FHEM-Betrieb ändert sich logischerweise der Verfügbarkeitsstatus. Den Zustand in FHEM verfügbar zu machen bzw. die Nutzung der events, scheint mir alleiniges Ziel der Nutzung von DevIO. Der Modulautor hat readyfnlist UND DevIO wie folgt implementiert:

Code Auswählen

sub X_Define($$)
.
  DevIo_CloseDev($hash);
.
  my $dev = $hash->{DeviceName};
  $readyfnlist{"$args[0].$dev"} = $hash;

sub X_Ready($)
.
    return DevIo_OpenDev($hash, 1, "X_Init");  # X_Init gibt immer undef zurück
.

sub X_Read($)
.
  #we dont really expect data here. Its just to gracefully close the device if the connection was closed
  my $buf = DevIo_SimpleRead($hash);

(Vorab: ich hab bereits auf non-blocking, also mit Callback_Funk, umgestellt und ein zusätzliches DevIO_Close vor dem DevIO_Open , wenn DevIo_IsOpen undefined ist, eingebaut. Ich denke, dass diese Modifikationen Sinn machen)
1. Frage: Macht es Sinn $readyfnlist(wird nur an dieser einen Stelle beim device-define gesetzt !) und DevIO kombiniert zu nutzen oder müsste nicht konsequenterweise dort ein DevIO_Open erfolgen ?
2. Frage: Über mein zusätzliches Logging sehe ich, dass im abgeschalteten Zustand permanent(mehrfach/Sek) von FHEM die X_Ready in einer Quasi-Schleife aufgerufen wird. Tatsächlicher Zugriff erfolgt aber nur wie erwartet jede Minute. Sollte man das aus Performancegründen trotzdem anders gestalten ?

Die Zustandsermittlung funktioniert mit dem obigen Code bei einem bestimmten Port des devices einwandfrei. Der disconnected-Zustand wird sofort erkannt. Der Reconnect wie erwartet innerhalb einer Minute. Nehme ich jetzt einen anderen Port des devices, so wird ein disconnect nach dem 1. connect nicht mehr erkannt. Das device ist vermeintlich immer connected. Meine Interpretation des Logauszugs: der disconnect wird zwar erkannt, aber sofort wird ein vermeintlicher reconnect erkannt(was nicht sein kann, da die Netzwerkverbindung definitiv tot ist.

Code Auswählen

2018.02.02 09:45:25 5:  Fernseher X_Ready(connection seems to be closed) OpenDev for DeviceName: 192.168.178.24:7676
2018.02.02 09:45:26 5:  Fernseher X_Ready(connection seems to be closed) OpenDev for DeviceName: 192.168.178.24:7676
.
.
2018.02.02 09:45:32 5: Fernseher X_Ready(connection seems to be closed) OpenDev for DeviceName: 192.168.178.24:7676
2018.02.02 09:45:32 5: HttpUtils url=http://192.168.178.24:7676/
2018.02.02 09:45:33 1: 192.168.178.24:7676 reappeared (Fernseher)
der TV wurde erkannt und wird nun wieder ausgeschaltet
2018.02.02 09:46:31 3: [STV] Fernseher STV_Read: connection DeviceName 192.168.178.24:7676 may be closed
2018.02.02 09:46:31 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.02 09:46:31 5: [STV] Fernseher STV_Ready(connection seems to be closed) OpenDev für DeviceName: 192.168.178.24:7676
2018.02.02 09:46:31 5: [STV] Fernseher STV_Ready(connection seems to be closed) OpenDev für DeviceName: 192.168.178.24:7676
2018.02.02 09:46:31 5: HttpUtils url=http://192.168.178.24:7676/
2018.02.02 09:46:31 1: 192.168.178.24:7676 reappeared (Fernseher)

Wie kann das letzte reappeared auftreten, obwohl das Gerät DeviceName: 192.168.178.24:7676 nicht im Netzwerk verfügbar ist ?
Was kann denn der Unterschied zwischen den beiden Ports sein ?

Und schließlich die letzte Frage: wäre es nicht sowieso sinnvoller den connected/disconnected Zustand über ein ping zu ermitteln und die events über Readings zu erzeugen ?

Danke und Grüße Markus

Markus Bloch · 02 Februar 2018, 12:18:42

Hast du den Artikel https://wiki.fhem.de/wiki/DevIo bereits studiert?

KölnSolar · 02 Februar 2018, 12:35:45

Ja, deshalb wundert mich ja die gleichzeitige Nutzung von readyfnlist u. DevIO. Aber ich vermute halt, dass sich der Modulautor etwas dabei gedacht hat, was ich mit meinem rudimentären Wissen nicht beurteilen kann.

Markus Bloch · 02 Februar 2018, 12:41:17

DevIo kümmert sich selbstständig um den Eintrag in %readyfnlist. Da muss der Modulautor an sich erstmal nicht nachhelfen. Es mag Ausnahmen geben, aber mir fällt spontan keine ein.

Gruß
Markus

Markus Bloch · 02 Februar 2018, 12:45:25

In diesem Fall wird %readyfnlist sozusagen "missbraucht" um das Öffnen der Verbindung über die ReadyFn auszulösen. Ich vermute man möchte damit die Logmeldung von DevIo bei der initialen Verbindung unterdrücken:

Code Auswählen

2018.02.02 12:44:39.130 3: Opening LANCUL device 192.168.179.20:1000
2018.02.02 12:44:39.181 3: LANCUL device opened

Ist aber nur meine persönliche Vermutung.

KölnSolar · 02 Februar 2018, 13:35:57

Hallo Markus,
habs dann jetzt mal umgebaut. Außer der von Dir angesprochenen Veränderung, bleibt scheinbar alles beim Alten $:-\$

Damit wäre ja die erste Frage eigentlich beantwortet. Hast Du Zeit auch die anderen Fragen zu beantworten ? Kann auch später sein.

Zu der 2. Frage hab ich jetzt nochmal im wiki geguckt und da ist es eigentlich genau so wie in dem Modul. Mich wunderten halt die massenhaften Aufrufe der X_Ready-Funktion. In der Regel ist der Fernseher ja eher aus als an, so dass FHEM ständig die X_Ready aufruft. $:-\$

Am brennendsten interessiert mich aber eigentlich, warum sich die 2 Ports am device unterschiedlich verhalten, also bei dem 2. Port eine Verbindung vermeintlich erkannt wird, obwohl es die physisch gar nicht gibt.

Danke & Grüße
Markus

Markus Bloch · 02 Februar 2018, 14:04:46

Hallo Markus,

ohne das Modul genauer in seinem Verhalten zu kennen, findet sich dort folgende Zeile:

Code Auswählen

$hash->{NEXT_OPEN} = 0; # force NEXT_OPEN used in DevIO

Diese sorgt für einen unverzüglichen Aufruf der ReadyFn wie Du es offenbar auch erlebst.

Du sprichst immer von 2 Ports? Welche genau meinst Du? Ich sehe nur den Port 7676 der hier geprüft wird. Warum der nach dem Ausschalten plötzlich connected ist ist durchaus seltsam. Evtl. mal mit nem Wireshark oder tcpdump tracen was da genau auf der Netzwerkschnittstelle abgeht.

Gruß
Markus

rudolfkoenig · 02 Februar 2018, 14:12:32

ZitatIn der Regel ist der Fernseher ja eher aus als an, so dass FHEM ständig die X_Ready aufruft

DevIo geht eigentlich von dem anderen Zustand aus, wurde urspruenglich fuer ein direkt eingestecktes USB Geraet wie CUL gebaut.

readyfnlist ist fuer diesen Fall sicher nicht optimal. Vermutlich waere es sinnvoller das Reconnect ueber einen InternalTimer zu versuchen, bin nur unsicher, inwieweit wir das kompatibel zu der alten Loesung hinkriegen.

KölnSolar · 02 Februar 2018, 16:44:33

Direkt 2 Experten. Suuper, Daaanke.

ZitatDevIo geht eigentlich von dem anderen Zustand aus, wurde urspruenglich fuer ein direkt eingestecktes USB Geraet wie CUL gebaut.

Hab ich mir so gedacht. Deshalb halte ich das fast auch für den falschen Weg über Devio und besser über einen simplen Ping und internaltimer. Ich weiß nur (noch) nicht, ob mir dann vielleicht Funktionalität verloren geht, womit wir bei Markus's Unverständnis des 2. Ports wären:

Leider lässt sich der Hersteller immer was Neues zur Kommunikation einfallen und was er macht, behält er auch als Firmengeheimnis für sich.

So ist bei meinem (alten) Modell, und dafür ist auch das ursprüngliche Modul ausgerichtet, auf einem Port 55000(der funktionierende Port) das senden von RC-Befehlen vorgesehen. Über einen weiteren Port 7676 lassen sich DMR-Funktionen nutzen.
Neuere Geräte handeln die RC-Befehle völlig anders über websockets. Der Port 55000 ist nicht mehr offen. Die RC-Befehle über websockets haben wir so weit auch erfolgreich integriert. Jetzt klemmt es halt an einem ordentlichen Status/event des devices und da dachte ich mir, nehme ich doch einfach den Port 7676 des DMR. Aber da reagiert DevIO eben völlig anders.

ZitatWarum der nach dem Ausschalten plötzlich connected ist ist durchaus seltsam.

Mit meinem beschränkten Wissen über TCP/IP und FHEM kann ich mir leider keinen Reim darauf machen, ob ich etwas falsch mache oder es einfach gar nicht gehen kann

Nach meinem Verständnis muss ich doch nur DevName mit IP:Port befüllen und das war's......Dachte ich $:-\$ Und, wenn es eben einfach nicht geht, würde ich an irgendeiner Stelle eine entsprechende Reaktion von DevIO/MainLoop erwarten, dass z.B. die Verbindung nicht aufgebaut werden kann oder trotz "physischer" Verbindung die Verbindung vom TV wieder beendet wird oder oder oder

Mit wireshark hatte ich schon probiert, aber da sehe ich ja nur die Kommunikation vom TV<->Windows und nicht von meinem Rpi zum TV.

Mit evtl. vergleichbaren Linux-Tools kenne ich mich überhaupt nicht aus u. hab (glaub ich) auch keine GUI auf dem Rpi.

Vielleicht fällt Euch ja noch was ein

Ach so

Zitatohne das Modul genauer in seinem Verhalten zu kennen, findet sich dort folgende Zeile:
$hash->{NEXT_OPEN} = 0; # force NEXT_OPEN used in DevIO
Diese sorgt für einen unverzüglichen Aufruf der ReadyFn wie Du es offenbar auch erlebst.

Nein, eben nicht. Im Falle des funktionierenden Ports 55000 erfolgt der Aufruf der X_Ready permanent. Den tatsächlichen TCP/IP-Aufbauversuch sieht man aber nur jede Minute.

Code Auswählen

2018.02.02 08:11:06 3: [STV] Fernseher defined with host: 192.168.178.24 port: 55000
2018.02.02 08:11:06 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
2018.02.02 08:11:06 1: 192.168.178.24:55000 reappeared (Fernseher)
2018.02.02 08:11:38 3: [STV] STV_Read: SimpleRead  für 192.168.178.24:55000
2018.02.02 08:11:38 1: 192.168.178.24:55000 disconnected, waiting to reappear (Fernseher)
2018.02.02 08:11:39 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
2018.02.02 08:11:39 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
.
.
150 Wiederholungen später
.
2018.02.02 08:12:37 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
2018.02.02 08:12:39 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
2018.02.02 08:12:39 5: HttpUtils url=http://192.168.178.24:55000/
2018.02.02 08:12:42 4: [STV] Fernseher TV_Callback_Connect(connection seems to be closed) message: connect to http://192.168.178.24:55000 timed out
2018.02.02 08:12:43 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
2018.02.02 08:12:44 3: [STV] STV_Ready(connection seems to be closed) OpenDev für 192.168.178.24:55000
.

KölnSolar · 03 Februar 2018, 12:24:25

Ich hab jetzt mal DevIO und $readyfnlist komplett rausgenommen. Die Funktion scheint grundsätzlich unverändert(also ist scheinbar keine dauerhafte Verbindung für die Funktion des Moduls erforderlich, abgesehen vom Status connected/disconnected)

Für den Status nehme ich jetzt HttpUtils_NonblockingGet. Mit dem seltsam reagierenden Port IP:7676 bekomme ich ein "connection refused" zurück. Erklärt das das seltsame Verhalten ?

Da ich noch andere Ports für die Statusermittlung nutzen kann, bediene ich mich nun derer.

Schönes Wochenende
Markus

KölnSolar · 04 Februar 2018, 13:47:33

und noch etwas detaillierter: mit GET u. leerem header liefert HttpUtils_NonblockingGet zurück:
der "funktionierende" Port 55000 liefert code="" u. Err="empty answer received" zurück.
der "problematische" Port 7676 liefert code=400 u. Err="" zurück.

Also ein Bug in DevIO ?

rudolfkoenig · 04 Februar 2018, 21:19:24

ZitatAlso ein Bug in DevIO ?

Um das zu beurteilen brauche ich mindestens ein "attr global verbose 5" log.
Und warum Du der Ansicht bist, dass das ein Bug ist.
HTTP 400 ist doch "Bad request: The client should not repeat this request without modification".

KölnSolar · 04 Februar 2018, 22:25:12

Ja eben. Aber Devio hat ihn ja als reconnected(siehe 1. Post) gemeldet und kommt nie(auch nicht, wenn das device dann ganz aus dem Netz ist, in den Zustand disconnected)
Ich mach mal ein Log.....

rudolfkoenig · 05 Februar 2018, 09:49:25

DevIo hat keine Ahnung von HTTP, es verwendet nur den nicht blockierenden connect Teil der HttpUtils Routinen, und behandelt die Verbindung als eine TCP/IP Verbindung. Wenn die Verbindung niemend zumacht, dann bleibt sie offen.

KölnSolar · 05 Februar 2018, 21:26:25

Hm ja, aber eben ominös. Selbes Modul und Port 55000 funktioniert perfekt, während Port 7676 sich seltsam verhält. Auch die Erzeugung des Logs mit global verbose 5 hat mir doch glatt die Sprache verschlagen(vielleicht erkennst Du ja was an diesem seltsamen Verhalten)

Code Auswählen

Define des Fernsehers; Fernseher ist im Netzwerk erreichbar

2018.02.04 23:45:27 3: [STV] Fernseher defined with host: 192.168.178.24 port: 7676 mode: DLNA_Client
2018.02.04 23:45:27 3: [STV] Fernseher  You are using a deprecated MAC detection mechanism using ifconfig.
2018.02.04 23:45:27 3: [STV] Fernseher  Please install Pearl Modules libnet-address-ip-local-perl and libio-interface-perl
2018.02.04 23:46:28 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.04 23:47:25 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.04 23:47:25 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.04 23:48:25 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.04 23:48:25 1: 192.168.178.24:7676 reappeared (Fernseher)
und so weiter
2018.02.04 23:52:25 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.04 23:52:26 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.04 23:53:26 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.04 23:53:26 1: 192.168.178.24:7676 reappeared (Fernseher)

Logging global mit verbose 5 gestartet und TV abgeschaltet(keine Netzwerkverbindung)

2018.02.04 23:53:45 5: Starting notify loop for global, 1 event(s), first is ATTR global verbose 5
.
.
Nicht eine Zeile mit Bezug zur IP oder dem devicename
.
.
2018.02.04 23:56:57 5: Cmd: >attr global verbose 3<

TV eingeschaltet und global verbose wieder auf 5

2018.02.05 00:06:42 5: Starting notify loop for global, 1 event(s), first is ATTR global verbose 5
.
.
NICHTS
.
2018.02.05 00:08:17 5: Cmd: >attr global verbose 3<

Und jetzt kommts. Nichts in FHEM gemacht, TV blieb eingeschaltet und dann 1h 50'(oder 2h nach abschalten vorm wiedereinschalten) später

Code Auswählen

2018.02.05 01:55:22 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 01:55:22 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 01:56:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 01:56:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 01:57:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 01:57:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 01:58:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 01:58:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 01:59:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 01:59:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 02:00:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 02:00:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 02:01:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 02:01:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 02:02:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 02:02:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 02:03:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
2018.02.05 02:03:04 1: 192.168.178.24:7676 reappeared (Fernseher)
2018.02.05 02:04:04 1: 192.168.178.24:7676 disconnected, waiting to reappear (Fernseher)
.
.
.

Einzige laienhafte Erklärung für das ständige disconnect/reappeared: Die Verbindung wird jeweils aufgebaut und sofort wieder vom TV abgebaut. Geprüft wird durch die Mainloop dann ja erst wieder 1' später. Wieso aber nach dem Abschalten kein disconnect mehr kommt kann ich noch nicht einmal mehr spekulieren. Und warum dann 2h später "plötzlich" wieder Prüfungen und Verbindungversuche erfolgen....

Ich finds einfach nur Irre und wenn Du keine Idee hast, belasse ich es dabei. Ich habs ja jetzt eh anders realisiert, sprich eine eigene Prüfung mit internaltimer 60, damit im disconnect-Fall nicht permanent X_Ready aufgerufen wird.

Danke&Grüße
Markus
Edit: und die 1. Meldung nach den 2h ist ein disconnect. Heißt doch, dass die Main-Loop 2h ein vorhandenes Readyfnlist vom letzten Devio_Open nicht beachtet hat, oder ? $:-\$