DevIo_Open & fhem shutdown restart

[olwaldi]

Ich bastel ja seit Anfang des Jahres verstärkt am Modul 70_DENON_AVR.pm und habe hier auch schon viele Tips bekommen - etwa bzgl. des Ausbauens von DENON_AVR_notify.

Da ich bei der Migration meiner Harmony-Fernbedienungsinfrastruktur hin zur neuen Sofabaton U3 einiges in meine 99_myUtilities eingebaut habe, insbesondere eine Stackverwaltung zum Senden von IR-Codes (zu "schnelles" Senden geht schief), habe ich eine ähnliche Stackverwaltung in 70_DENON_AVR.pm eingebaut. Laut Denon-Spec darf man auch nicht zu schnell Anfragen an den AVR schicken - jetzt warte ich immer 0.1s zwischen zwei DevIo_SimpleWrite. Beim Testen des neuen Stacks ist mir aufgefallen, daß 70_DENON_AVR 3x parallel versucht, den AVR via DevIo_OpenDev zu kontaktieren. Klar, war ein Fehler in 70_DENON_AVR (entweder von mir oder geerbt vom ursprüngllichen Entwickler) - siehe https://forum.fhem.de/index.php?topic=58452.msg1369571#msg1369571

Diese Mehrfachaufruf habe ich unterbinden können. Es verbleiben aber zwei Merkwürdigkeiten:

1. Nach einigen Tests mit vielen reloads lief Alles wie gewünscht. Dann für einige Stunden was ganz anderes gemacht, um dann einfach nur fernzugucken (dann wird 70_DENON_AVR genutzt). Und dann hat das Modul komplett nicht mehr funktioniert, hat z.B. keine Events generiert. Erst nach zweimaligem shutdown restart hat wieder Alles funktioniert. Ich kann mir das nur so erklären, daß durch zu häufige reloads fhem als Ganzes "durcheinader" kommt. Aber seither tut Alles wie's soll.

2. 70_DENON_AVR hat das Attribut disable, um das Modul temporär zu deaktivieren. Auch da habe ich Änderungen vorgenommen. Es funktioniert wie gewünscht, das DevIo_OpenDev öffnet die IP-Verbindung erwartet schnell (die "Set (?)" werden von der fhem-WebGUI ausgelöst, um Hilfe anzuzeigen):

Code Auswählen Erweitern

2026.10.03 10:42:15 4: DENON_AVR Denon: entering DENON_AVR_Set (?).
2026.10.03 10:42:33 4: DENON_AVR Denon: calling DENON_AVR_Attr set disable 0
2026.10.03 10:42:33 4: DENON_AVR Denon: calling DENON_AVR_Connect.
2026.10.03 10:42:33 3: Opening Denon device 192.168.178.66:23
2026.10.03 10:42:33 4: IP: 192.168.178.66 -> 192.168.178.66
2026.10.03 10:42:33 4: DENON_AVR Denon: entering DENON_AVR_Set (?).
2026.10.03 10:42:33 4: DENON_AVR Denon: calling DENON_AVR_DoInit
2026.10.03 10:42:33 4: DENON_AVR Denon: entering DENON_AVR_StatusRequest.
2026.10.03 10:42:33 4: DENON_AVR Denon: calling DENON_WriteDelayed, CV? <query>. wait=0.1 (remaining 0)
2026.10.03 10:42:33 4: DENON_AVR Denon: leaving DENON_AVR_StatusRequest.
2026.10.03 10:42:33 3: Denon device openedAber nach einem "shutdown restart" liegen bis zu 10s zwischen den DevIo-Meldungen "Opening..." und "...opened". Es werden (soweit ich das testen konnte) exakt dieselben perl-subs aufgerufen. Klar, beim restart wird ja nicht nur das define aufgerufen sonderrn z.B. auch Attribute & states gesetzt.

Eine derartig lange Verzögerung sehe ich z.B. auch beim Öffnen der IP-Verbindung zu unserem Blockheizkraftwerk Dachs via modbus - also ganz andere Baustelle.

Ist das normal (stören tut's nicht wirklich) oder hat "mein" fhem irgendein Setup-Problem?


Grüßle, Michael

 

[rudolfkoenig]

Zwischen Opening und opened liegt:
- Namensaufloesung/DNS (ist attr global dnsServer gesetzt?)
- TCP connect
- evtl SSL handshake.
- Initialisierung per DENON_AVR_DoInit

Mehr Details duerfte man man mit "attg global verbose 5" rauskriegen.
Das gilt auch fuer Problem #1

[olwaldi]

Danke für die Hinweise.

In global gibts tatsächlich ein paar Security-Meldungen bzgl. telnet und FHEMWEB WEBapi. Beide sind absichtlich nicht paßwortgeschützt, da aus Bash-Skripten ohne Paßwort zugegriffen wird. DNS sollte keine Rolle spielen, da ich die IP-Adressen explizit nutze. [Die lokale DNS-Auflösung via Fritzbox klappt nicht, wenn ich den Domainnamen fritz.box weglasse.] In global ist dnsServer aktuell nicht gesetzt.

D.h. ich werde mal genauer prüfen, was ich in global richtigerweise setzen sollte.


Grüßle, Michael

[olwaldi]

Mit dem höheren verbose-Wert von global konnte ich den Übeltäter finden:

Code Auswählen Erweitern

2026.10.06 16:18:37 1: usb create starting
...
2026.10.06 16:18:45 1: usb create end
Dort scheitern (richtigerweise) alle Checks mit je 1s Timeout. D.h. "meine" Programmänderungen an DENON_AVR sind wohl nicht "schuld", was mich erstmal beruhigt.

Auch gefunden: Einige FHEM-Module nutzen vermutlich FHEM::Meta nicht richtig, z.B.

Code Auswählen Erweitern

2026.10.06 16:18:36 4: FHEM::Meta::__GetMaintainerdata ERROR: Orphan module entry:
  FHEM/10_MQTT_BRIDGE.pm hexenmeister MQTT
...
Aber das kostet keine Startup-Zeit.

Ich habe aber auch eine Überraschung gefunden: Beim Lesen von fhem.cfg werden ja auch DENON_AVR-Attribute gesetzt, dabei als (beabsichtigter) Seiteneffekt DENON_AVR_StatusRequest aufgerufen. Ich hatte bislang geglaubt, daß erst während des DENON_AVR_DoInit in DevIo_DevOpen(...,"DENON_AVR_DoInit", ... ) der DENON_AVR_StatusRequest aufgerufen wird. Stattdessen triggert das schon früher beim Attribut-Setzen. D.h. WÄHREND DevOpen läuft gibts eine Art "Taskswitch" BEVOR DoInit aufgerufen wird. Dagegen ist allerdings DENON_AVR "robust" durch geeignete helper-Attribute.

In dem Zusammenhang war ich auch überrascht, daß DevIo_IsOpen innerhalb von DoInit false bleibt, d.h. hier setze ich ein helper-Attribut, um vor Mehrfach-Aufrufen zu schützen. Das Attribut lösche ich, sobald der Callback von DevIo_OpenDev aufgerufen wird.

Zusammengefaßt: Wartezeit verstanden, kein echtes Problem in DENON_AVR.


Grüßle, Michael

[rudolfkoenig]

2026.10.06 16:18:37 1: usb create starting

Das ist initialUsbCheck geschuldet, und soll die angeschlossenen seriellen und USB Geraete erkennen.
Ich wuerde es nach dem ersten Start deaktivieren.

[Beta-User]

10_MQTT_BRIDGE wird nicht mehr aktiv verteilt, wer es nutzt, sollte zur generic Bridge wechseln, sonst einfach löschen...

Reaktionen auf Attribute sollte man nicht vor $init_done nach außen geben, diese Prüfungen gehören in die start-Timer-Funkion.