Problem mit DevIO.pm

[roelleke]

Nach dem heutigen Update startet mein Fhem-Server nicht mehr. Nach dem zurückspielen der alten DevIO.pm funktioniert er wieder.
Ich habe kein Ahnung was sich hier verändert hat. Für hinweise ob es an meine Konfigurationliegen kann oder ob sich ein Fehler beim Update eingeschlichen hat wäre ich dankbar.
Zunächst hab eich DevIo vom update ausgeschlossen.

[rudolfkoenig]

Wenn wir daran was aendern sollten, dann waere ein Hinweis darauf, was schiefgeht, vmtl. hilfreich.

[roelleke]

So ich habe gesucht und glaube etwas gefunden zu haben.
Im log steht folgendes:

Code: [Auswählen]

2020.06.05 11:48:22 3: Opening nanoCUL device /dev/serial/by-path/platform-3f980000.usb-usb-0:1.3:1.0-port0
2020.06.05 11:48:22 1: nanoCUL: Can't connect to /dev/serial/by-path/platform-3f980000.usb-usb-0:1: Invalid argument
2020.06.05 11:48:22 3: Opening WlanCUL device 10.0.0.64:23
2020.06.05 11:48:22 3: WlanCUL: Possible commands: ABCEeFfGiKLlMmRTtUuVWXxY
2020.06.05 11:48:22 3: WlanCUL device opened
2020.06.05 11:48:22 3: Opening WlanCUL2 device 10.0.0.63:23
2020.06.05 11:48:22 3: WlanCUL2: Possible commands: ABCeFfGiKLlMNRTtUVWXx
2020.06.05 11:48:22 3: WlanCUL2 device opened
2020.06.05 11:48:22 3: Opening WlanSignalDuino1 device 10.0.0.101:23
2020.06.05 11:48:22 3: WlanSignalDuino1: Attr, setting debug to: 0
2020.06.05 11:48:22 3: Opening Signalduino2 device /dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0
2020.06.05 11:48:22 1: Signalduino2: Can't connect to /dev/serial/by-path/platform-3f980000.usb-usb-0:1: http:///dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0: malformed or unsupported URL
2020.06.05 11:48:22 3: Signalduino2: Connect, http:///dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0: malformed or unsupported URL
2020.06.05 11:48:22 1: define Signalduino2 SIGNALduino /dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0@57600: http:///dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0: malformed or unsupported URL

Mit der alten DevIo funktioniert es Problemlos und es hat auch seit Jahren funktioniert.

[rudolfkoenig]

So ich habe gesucht ...

Danke.
Halten wir fest: der FHEM-Server startet sehr wohl, "nur" Signalduino funktioniert nicht.

Ich habe DevIo.pm angepasst, damit dieses Pfad nicht als Netzwerkadresse betrachtet wird, bitte testen.
FHEM update gibt es morgen ab acht, DevIo.pm aus dem SVN ab sofort.

[roelleke]

Hallo,

danke für die superschnelle Reaktion. Ich have mir die DevIo aus dem SVN geholt und auspribiert.
Jetzt funktioniert es wieder wie vorher.

Allerdings war das Problem nicht nur der Signalduino, sonder der Fhem-Server befand sich in einer Startschleife. Wahrscheinlich immer wenn er auf einen Signalduino zugreifen wollte startete er neu.

Aber jetzt ist alles wieder in Ordnung.
Vielen Dank

[rudolfkoenig]

Wahrscheinlich immer wenn er auf einen Signalduino zugreifen wollte startete er neu.

Das ist unwahrscheinlich.
Falls es och der Fall sein sollte, wuerde ich es gerne untersuchen.

[roelleke]

JA, ob es am Signalduino lag weiß ich nicht, aber die Startschleife war auf jedenfall da.
Für mich sieht das im Log so aus. Ob es nun am Signalduino oder an der DevIo liegt weiß ich nicht.

Hier ist mal ein Auszug aus dem Log mit der Fehlerhaften DevIo:

Code: [Auswählen]

myMQTTserver: port 1884 opened
2020.06.05 08:40:45 3: DashButton1: listening
2020.06.05 08:40:48 3: AptToDate (fhemServer) - defined
2020.06.05 08:40:50 3: Benzin: Defined with URL https://www.clever-tanken.de/tankstelle_details/12070 and interval 3600 featurelevel 6.0
2020.06.05 08:40:50 3: Benzin1: Defined with URL https://www.clever-tanken.de/tankstelle_details/12430 and interval 3600 featurelevel 6.0
2020.06.05 08:40:50 3: Benzin2: Defined with URL https://www.clever-tanken.de/tankstelle_details/47810 and interval 3600 featurelevel 6.0
2020.06.05 08:40:50 3: Benzin3: Defined with URL https://www.clever-tanken.de/tankstelle_details/28165 and interval 3600 featurelevel 6.0
2020.06.05 08:40:52 3: [myTwilight] got no weather info from yahoo. Error code: http://query.yahooapis.com/v1/public/yql?q=select%20*%20from%20weather.forecast%20where%20woeid=0%20and%20u=%27c%27&format=json&env=store%3A%2F%2Fdatatables.org%2Falltableswithkeys: Can't connect(1) to http://query.yahooapis.com:80: IO::Socket::INET: Bad hostname 'query.yahooapis.com:80'
2020.06.05 08:40:53 0: OctoPrint Ender5 [OctoPrint_Define] start device
2020.06.05 08:40:56 3: DeskLight: Defined with URL http://10.0.0.39/all and interval 600 featurelevel 6.0
2020.06.05 08:40:57 1: Including ./log/fhem.save
2020.06.05 08:41:01 3: DashButton1: stopped
2020.06.05 08:41:02 3: DashButton1: listening
2020.06.05 08:41:46 3: wsPort: port 8080 opened
2020.06.05 08:41:46 2: [Freezemon] myFreezemon: ready to watch out for delays greater than 4 second(s)
2020.06.05 08:41:46 0: Featurelevel: 6.0
2020.06.05 08:41:46 0: Server started with 915 defined entities (fhem.pl:22082/2020-05-31 perl:5.024001 os:linux user:fhem pid:27241)
2020.06.05 08:41:48 3: WlanSignalDuino1: IdList, development version active, development attribute = 1
2020.06.05 08:41:48 3: WlanSignalDuino1: IdList, attr whitelist: 3,3.1,4,8,10,17,17.1,18,52,55,59,60,62,65,66,67,87
2020.06.05 08:41:48 3: WlanSignalDuino1: IdList, MS 3 3.1 4 17 55 65 87
2020.06.05 08:41:48 3: WlanSignalDuino1: IdList, MU 8 17.1 59 60 62 66 67
2020.06.05 08:41:48 3: WlanSignalDuino1: IdList, MC 10 18 52
Can't use an undefined value as a subroutine reference at ./FHEM/00_SIGNALduino.pm line 3077.
2020.06.05 08:41:49 1: Including fhem.cfg
2020.06.05 08:41:49 3: telnetPort: port 7072 opened

und hier mit der neuesten DevIO aus dem SVN:

Code: [Auswählen]

2020.06.01 08:58:15 3: myMQTTserver: port 1884 opened
2020.06.01 08:58:16 3: DashButton1: listening
2020.06.01 08:58:19 3: AptToDate (fhemServer) - defined
2020.06.01 08:58:21 3: Benzin: Defined with URL https://www.clever-tanken.de/tankstelle_details/12070 and interval 3600 featurelevel 6.0
2020.06.01 08:58:21 3: Benzin1: Defined with URL https://www.clever-tanken.de/tankstelle_details/12430 and interval 3600 featurelevel 6.0
2020.06.01 08:58:21 3: Benzin2: Defined with URL https://www.clever-tanken.de/tankstelle_details/47810 and interval 3600 featurelevel 6.0
2020.06.01 08:58:21 3: Benzin3: Defined with URL https://www.clever-tanken.de/tankstelle_details/28165 and interval 3600 featurelevel 6.0
2020.06.01 08:58:23 3: [myTwilight] got no weather info from yahoo. Error code: http://query.yahooapis.com/v1/public/yql?q=select%20*%20from%20weather.forecast%20where%20woeid=0%20and%20u=%27c%27&format=json&env=store%3A%2F%2Fdatatables.org%2Falltableswithkeys: Can't connect(1) to http://query.yahooapis.com:80: IO::Socket::INET: Bad hostname 'query.yahooapis.com:80'
2020.06.01 08:58:23 0: OctoPrint Ender5 [OctoPrint_Define] start device
2020.06.01 08:58:27 3: DeskLight: Defined with URL http://10.0.0.39/all and interval 600 featurelevel 6.0
2020.06.01 08:58:28 1: Including ./log/fhem.save
2020.06.01 08:58:32 3: DashButton1: stopped
2020.06.01 08:58:32 3: DashButton1: listening
2020.06.01 08:59:17 3: wsPort: port 8080 opened
2020.06.01 08:59:17 2: [Freezemon] myFreezemon: ready to watch out for delays greater than 4 second(s)
2020.06.01 08:59:17 0: Featurelevel: 6.0
2020.06.01 08:59:17 0: Server started with 918 defined entities (fhem.pl:22082/2020-05-31 perl:5.024001 os:linux user:fhem pid:521)
2020.06.01 08:59:19 2: AttrTemplates: got 174 entries
2020.06.01 08:59:20 3: WlanSignalDuino1: IdList, development version active, development attribute = 1
2020.06.01 08:59:20 3: WlanSignalDuino1: IdList, attr whitelist: 3,3.1,4,8,10,17,17.1,18,52,55,59,60,62,65,66,67,87
2020.06.01 08:59:20 3: WlanSignalDuino1: IdList, MS 3 3.1 4 17 55 65 87
2020.06.01 08:59:20 3: WlanSignalDuino1: IdList, MU 8 17.1 59 60 62 66 67
2020.06.01 08:59:20 3: WlanSignalDuino1: IdList, MC 10 18 52
2020.06.01 08:59:20 3: Signalduino2: IdList, development version active, development attribute = 1
2020.06.01 08:59:20 3: Signalduino2: IdList, attr whitelist: 3,3.1,4,8,10,18,19,32,33,33.1,48,58,60,64,66,67,85,87
2020.06.01 08:59:20 3: Signalduino2: IdList, MS 3 3.1 4 33 33.1 87
2020.06.01 08:59:20 3: Signalduino2: IdList, MU 8 19 32 48 60 64 66 67 85
2020.06.01 08:59:20 3: Signalduino2: IdList, MC 10 18 58
2020.06.01 08:59:20 3: Signalduino2: SimpleWrite_XQ, disable receiver (XQ)
2020.06.01 08:59:20 3: Signalduino2: StartInit, get version, retry = 0
2020.06.01 08:59:24 1: WlanSignalDuino1: DoInit, 10.0.0.101:23@57600
2020.06.01 08:59:24 3: WlanSignalDuino1 device opened


[Icinger]

2020.06.05 08:40:57 1: Including ./log/fhem.save

2020.06.01 08:58:28 1: Including ./log/fhem.save

Hat dein Server ne Zeitreise gemacht???

[rudolfkoenig]

Can't use an undefined value as a subroutine reference at ./FHEM/00_SIGNALduino.pm line 3077.

Das ist ein Fehler im SIGNALduino Modul (ursache der Crash), und sollte dem Maintainer gemeldet werden.

[Sidey]

Hi Rudi,

Da wäre ich mir jetzt nicht ganz 100%ig sicher ob es wirklich "nur" ein Fehler im SIGNALduino ist.
Ich muss gestehen, meine Routinen sind nicht so robust, dass sie damit zurecht kommen, wenn an dem Gerätehash etwas verändert bzw. dieser komplett gelöscht wird. :-(

Denn meiner Analyse nach, löscht commandDefine den Gerätehash, wenn der Define Befehl nicht geklappt hat:
https://svn.fhem.de/trac/browser/trunk/fhem/fhem.pl?rev=22120#L2091

Es löscht aber nicht die InternalTimer und das wird hier zum Verhängnis.

Drei Stellen, an denen ich hier Optimierungspotential gefunden habe:

1) UndefFn vom Modul aufrufen, bevor der Gerätehash gelöscht wird. Hat der Maintainer sauber gearbeitet, löscht er auch alle noch laufenden Timer.
2) In allen Routinen eines Modules, die über callbacks aufgerufen werden, prüfen ob der übergebene Gerätehash valide ist.
3) In FHEM (z.B. 99_utils) generell die Funktion Bereitstellen, welche den Gerätehash und Warnungen liefert:

Code: [Auswählen]

sub getDefinition {
    my $name = shift // carp q[name noch specified];
    return $::defs{$name} // carp q[definition of $name does not exist];
}

Vermutlich gibt es weitere Stellen, an denen verbessert werden könnte.


Grüße Sidey

[Ralf9]

Demnach ist es sinnvoll beim UndefFn vom Modul alle InternalTimer zu löschen. Wenn der USB gezogen wird, könnte ja gerade jeder InternalTimer laufen.

Code: [Auswählen]

RemoveInternalTimer($hash);
RemoveInternalTimer("HandleWriteQueue:$name");
RemoveInternalTimer("sduino_IdList:$name");

Dies fehlt evtl auch noch bei einigen anderen Modulen

Gruß Ralf

[herrmannj]

Demnach ist es sinnvoll beim UndefFn vom Modul alle InternalTimer zu löschen. Wenn der USB gezogen wird, könnte ja gerade jeder InternalTimer laufen.

Code: [Auswählen]

RemoveInternalTimer($hash);
RemoveInternalTimer("HandleWriteQueue:$name");
RemoveInternalTimer("sduino_IdList:$name");

Dies fehlt evtl auch noch bei einigen anderen Modulen

Gruß Ralf

Das sollte eigentlich für jeden Modulautor Standard sein.

[rudolfkoenig]

Da wäre ich mir jetzt nicht ganz 100%ig sicher ob es wirklich "nur" ein Fehler im SIGNALduino ist.

Vermutlich nicht nur, aber SIGNALduino muss es jetzt ausbaden.

CommandDefine loescht _nicht_ den Geraetehash, es entfernt ihn nur aus dem globalen %defs.
Natuerlich werden bei einem abgelehnten define keine InternalTimer entfernt, diese sind nicht immer einem Geraet zuzuordnen.

Ein Modul sollte keine InternalTimer definieren, wenn es define ablehnt.
UndefFn aufzurufen, nachdem DefFn "nein" gesagt hat, ist mAn paranoid, und soweit bin ich noch nicht.

Natuerlich koennte man statt globale Variablen jeweils Funktionen fuer den Zugriff anbieten, mir ist aber das Nutzen/Aufwand Verhaeltnis noch zu niedrig. FHEM profitiert von Leichtgewichtigkeit/minimalen Einschraenkungen, ich wuerde es gerne dabei belassen.

Demnach ist es sinnvoll beim UndefFn vom Modul alle InternalTimer zu löschen.

Klar.
Das wird das Problem "InternalTimer Aufruf nach abgelehnten define" aber nicht loesen.

[Sidey]

Ja, sollte es.

Ich kann sagen, ich war bis gestern der Meinung war, dass ein

Code: [Auswählen]

RemoveInternalTimer($hash)

Ausreichend ist.
Aber dem ist nicht so


Grüße Sidey

Gesendet von meinem Moto Z (2) mit Tapatalk

[rudolfkoenig]

Korrektur: ich habe das Problem vermutlich falsch einsortiert, mein Beitrag von vorhin ist zwar vom Inhalt her nicht falsch, aber fuer dieses Problem vmtl. irrelevant.

- SIGNALduinos DefFn sagt nicht "nein", startet aber ein InternalTimer, und stellt die Verbindung asynchron her (wenn die Aussage "Log mit der Fehlerhaften DevIo" stimmt).
- SIGNALduino_IdList wird (vmtl. per InternalTimer, vor Herstellen der Verbindung) aufgerufen, und gibt etliches mit $hash->{logMethod} (!) aus (siehe: WlanSignalDuino1: IdList, development version active...).
- danach wird SIGNALduino_IdList vmtl. fuer eine andere Instanz(?) aufgerufen (die development Ausgabe kommt hier nicht), und stuerzt in der Zeile 3077 ab, weil $hash->{logMethod} nicht definiert ist.
- das Verhalten ist erklaerbar, wenn SIGNALduino_FW_saveWhitelist fuer eine nicht SIGNALduino Instanz aufgerufen wird. Klingt aber nicht sehr wahrscheinlich.

@roelleke: wieviele SIGNALduino Instanzen sind definiert? Wurde "beim" Absturz eine umbenannt?