FHEM Forum

CUL - Entwicklung => Fehlerberichte => Thema gestartet von: roelleke am 05 Juni 2020, 10:39:19

Titel: Problem mit DevIO.pm
Beitrag von: roelleke am 05 Juni 2020, 10:39:19
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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 05 Juni 2020, 10:44:24
Wenn wir daran was aendern sollten, dann waere ein Hinweis darauf, was schiefgeht, vmtl. hilfreich.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: roelleke am 05 Juni 2020, 11:59:53
So ich habe gesucht und glaube etwas gefunden zu haben.
Im log steht folgendes:


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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 05 Juni 2020, 13:55:16
ZitatSo 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.


Titel: Antw:Problem mit DevIO.pm
Beitrag von: roelleke am 05 Juni 2020, 15:30:13
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

Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 05 Juni 2020, 15:40:12
ZitatWahrscheinlich 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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: roelleke am 05 Juni 2020, 18:05:04
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:

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:


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
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Icinger am 05 Juni 2020, 18:10:17
Zitat2020.06.05 08:40:57 1: Including ./log/fhem.save
Zitat2020.06.01 08:58:28 1: Including ./log/fhem.save
Hat dein Server ne Zeitreise gemacht???
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 05 Juni 2020, 18:12:05
ZitatCan'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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Sidey am 06 Juni 2020, 00:44:32
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:

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
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Ralf9 am 06 Juni 2020, 11:04:29
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.
RemoveInternalTimer($hash);
RemoveInternalTimer("HandleWriteQueue:$name");
RemoveInternalTimer("sduino_IdList:$name");


Dies fehlt evtl auch noch bei einigen anderen Modulen

Gruß Ralf
Titel: Antw:Problem mit DevIO.pm
Beitrag von: herrmannj am 06 Juni 2020, 11:07:20
Zitat von: Ralf9 am 06 Juni 2020, 11:04:29
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.
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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 06 Juni 2020, 11:24:18
ZitatDa 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.

ZitatDemnach 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.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Sidey am 06 Juni 2020, 11:25:52
Ja, sollte es.

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


RemoveInternalTimer($hash)


Ausreichend ist.
Aber dem ist nicht so :(


Grüße Sidey

Gesendet von meinem Moto Z (2) mit Tapatalk

Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 06 Juni 2020, 12:12:29
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?
Titel: Antw:Problem mit DevIO.pm
Beitrag von: HomeAuto_User am 06 Juni 2020, 12:20:39
Hallo,

ich selbst war hiervon auch betroffen und suchte mir den Wolf.

Zitat von: rudolfkoenig am 06 Juni 2020, 12:12:29
@roelleke: wieviele SIGNALduino Instanzen sind definiert? Wurde "beim" Absturz eine umbenannt?

Ich bin zwar nicht roelleke aber aufgrund des selben Fehlers melde ich mich mit zu Wort.

Bei mir waren diesbezüglich 2 definierte Instanzen betroffen. Beim Absturz konnte ich nicht verzeichnen das eine umbenannt wurde. FHEM war in einer Schleife dadurch bis ich von Hand eingegriffen hatte.
Diese Erkenntnis kann ich auch auf ein 2. Haushalt beziehen wo es ebenso war.

MfG
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 06 Juni 2020, 12:25:47
War einer der Instanzen per Netzwerk angebunden?
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Ralf9 am 06 Juni 2020, 14:59:40
Das Problem war, daß der sduino mit "by-path" und nicht wie üblich mit "by-id" angebunden war.
/dev/serial/by-path/platform-3f980000.usb-usb-0:1.1.2:1.0-port0@57600
Die "by-path" Definition wurde als fehlerhafte IP abgelehnt:
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

ZitatEin Modul sollte keine InternalTimer definieren, wenn es define ablehnt.
Wie kann ich erkennen, wenn es define ablehnt?
Ist das am $ret von DevIo_OpenDev erkennbar? Wenn $ret defined und nicht leer?

Dann könnte man ein
RemoveInternalTimer("sduino_IdList:$name");
machen, wenn es define ablehnt

Gruß Ralf
Titel: Antw:Problem mit DevIO.pm
Beitrag von: HomeAuto_User am 06 Juni 2020, 15:02:39
Zitat von: rudolfkoenig am 06 Juni 2020, 12:25:47
War einer der Instanzen per Netzwerk angebunden?

Angeschlossen über USB mit DEF via path.

Zitat von: Ralf9 am 06 Juni 2020, 14:59:40
Das Problem war, daß der sduino mit "by-path" und nicht wie üblich mit "by-id" angebunden war.

Leider gibt es Fälle wo man mit by-id nicht auskommt. (Geräte mit selber ID)


Gesendet von iPhone mit Tapatalk Pro
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 06 Juni 2020, 15:17:24
ZitatWie kann ich erkennen, wenn es define ablehnt?
???
Ich meine nicht DevIo_OpenDev, sondern die Modul-Eigene DefFn.
Und da sollte der Maintainer schon wissen, in welchem Fall sie eine Fehlermeldung statt undef zurueckliefert.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: Ralf9 am 06 Juni 2020, 15:59:31
ZitatIch meine nicht DevIo_OpenDev, sondern die Modul-Eigene DefFn.
Und da sollte der Maintainer schon wissen, in welchem Fall sie eine Fehlermeldung statt undef zurueckliefert.

Ich meinte wie kann ich erkennen, wenn DevIo_OpenDev den connect z.B. wegen einem fehlerhaften define ablehnt?
Damit?
if ($ret) {
  ...


Titel: Antw:Problem mit DevIO.pm
Beitrag von: Sidey am 06 Juni 2020, 16:22:54
Die Anzahl an Definitionen ist für den Fehler uninteressant.

Der Timer der gestartet wird ruft SIGNALduino_IdList auf.
Ob die Verbindung zum physischen Gerät besteht ist für die Funktion nicht relevant.

Relevant ist aber, ob $defs{<Name>} den Gerätehash liefert.

Das klappt nicht, weil im Core dieser Key gelöscht wird.

Dass der Key vom Core gelöscht wird, ohne das undefFn aufgerufen wird, war mir einfach nicht transparent.

Ich denke robuster Code kommt zu großen Teilen aus den Modules aber durchaus auch aus dem Core.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: rudolfkoenig am 06 Juni 2020, 16:47:26
ZitatIch meinte wie kann ich erkennen, wenn DevIo_OpenDev den connect z.B. wegen einem fehlerhaften define ablehnt?
Bei einem Problem wird die Fehlermeldung dem callback mitgeteilt, falls sie spezifiziert wurde (d.h. asynchroner Ablauf fuer http/websocket), ansonsten kommt die Fehlermeldung im Rueckgabewert.

Aber danke fuer den Denkanstoss: im aktuellen Code liefert DevIo_OpenDev _mit_ callback je nach Fehler (z.Bsp. DNS-Problem ohne gesetzten dnsServer) _auch_ als Rueckgabewert (und nicht nur im callback). Das ist mAn irrefuehrend, und fuehrte(?) in diesem Fall zum Problem, weil SIGNALduino_Define diesen Wert zurueckgeliefert hat.
Ich habe DevIo.pm angepasst, damit beim gesetzten callback _nie_ ein Fehler direkt zurueckgeliefert wird, sondern nur uebers callback.


ZitatIch denke robuster Code kommt zu großen Teilen aus den Modules aber durchaus auch aus dem Core.
Das ist vermutlich richtig, es hat aber einen Preis und diverse Nebeneffekte.
Titel: Antw:Problem mit DevIO.pm
Beitrag von: roelleke am 06 Juni 2020, 17:46:13
Hallo,
komme erst gerade wieder dazu ins Forum zu schauen.

Ich have 2 Signalduinos angeschlossen. Einer über USB und der andere über LAN (Signalesp).
Ich habe keinen von beiden umbenannt und ich habe auch nicht erkennen können ob so etwas automatisch passiert, aber meiner Meinung ist nichts umbenannt worden.