[GELÖST]Plötzlich Fehler in FHEMWEB? Seitenaufruf führt zum Neustart von FHEM

OiledAmoeba · 03 März 2023, 02:37:06

Moin,

ich habe FHEM über FHEMWEB mit 'shutdown restart' neu gestartet, weil gassistant nicht mehr lief. Ich hatte die Hoffnung, das sich da nur was weggehängt hat und der Neustart hilft.
Tatsächlich habe ich nix anderes gemacht.

Wenn ich jetzt versuche, FHEMWEB zu öffnen, wirft er im Log nur diese Zeile:

Code Auswählen

Unmatched ( in regex; marked by <-- HERE in m/^( <-- HERE most$/ at ./FHEM/01_FHEMWEB.pm line 3047.
und anschließend startet FHEM neu.
Ich habe erfolgreich über Telnet 'attr global stacktrace 1' aktiviert, aber selbst da wird nichts protokolliert, bevor der Neustart kommt.

Laut nano steht in 3047

Code Auswählen

3047 if(defined($re) && $state =~ m/^$re$/) {

Wenn ich mir den ganzen Block ansehe, scheint der für devStateIcon zuständig zu sein. Aber da gab es weder Änderungen in meiner Installation in letzter Zeit, noch gab es bisher Probleme.

Code Auswählen

3043   if(defined($devStateIcon)) {
3044     my @list = split(" ", $devStateIcon);
3045     foreach my $l (@list) {
3046       my ($re, $iconName, $link) = split(":", $l, 3);
3047       if(defined($re) && $state =~ m/^$re$/) {
3048         if(defined($iconName) && $iconName eq "") {
3049           $rlink = $link;
3050           last;
3051         }
3052         if(defined($iconName) && defined(FW_iconName($iconName)))  {
3053           return ($iconName, $link, 0);
3054         } else {
3055           return ($state, $link, 1);
3056         }
3057       }
3058     }
3059   }

Bin jetzt nicht so der Perl-Crack, aber für mich passt die Anzahl der Klammern, ich sehe da keine offen gebliebene (...

Solange, wie ich nicht versuche über FHEMWEB auf das System zu kommen, läuft es einwandfrei. Sowie ich die Webseite öffnen will, kommt der Neustart...

Zeitstempel in der Datei: # $Id: 01_FHEMWEB.pm 27209 2023-02-12 14:45:51Z rudolfkoenig $

Jmd eine Idee, was da los ist?

Beta-User · 03 März 2023, 06:35:47

Die Klammer dürfte aus $re kommen, also aus einem von dir gesetzten devStateIcon-Attribut.

OiledAmoeba · 03 März 2023, 10:18:09

Moin,

danke für die Antwort. Das geisterte mir gestern im Bett statt der Schäfchen auch schon durch den Kopf, als ich über den Codeblock nachdachte. Bin dann aber zum Schluss gekommen, dass es das nicht sein könne, weil ja vor dem Neustart nix geändert wurde.

Die einzige Idee ist, dass es vllt ein Gerät ist, welches seit dem Neustart keinen auswertbaren Status besitzt und deshalb der Codeschnipsel dann ( als Ergebnis liefert.
Es muss eigentlich ein Gerät sein, welches in der bis gestern laufenden Instanz eine flüchtige Eigenschaft (Reading/Internal/whatever) besessen hat, die dann durch den Neustart verloren ging und jetzt bis zu dem Versuch, FHEMWEB zu öffnen, nicht wieder hergestellt wurde.

Habe gerade mal

Code Auswählen

perl fhem.pl 7072 'list -r devStateIcon=.*{.*' | grep 'devStateIcon' > grepStateIcon.txt
durch die Konsole gejagt um die zu finden, die perl-code enthalten und 41 Geräte mit dem Attribut gefunden. Einer von denen müsste es ja sein.
Ich unterstelle mal, dass es die, die einfach nur Dinge wie Initialized:10-px-kreis-gelb machen, nicht sein können, denn insgesamt haben 109 Geräte ein devStateIcon...

Beta-User · 03 März 2023, 10:35:44

Du suchst m.E. keinen Perl-Code, sondern eine regex, die im fraglichen Abschnitt (uU. auch in einem Teil weiter hinten) mit einer runden Klammer beginnt und bis zu einem Doppelpunkt keine schließende Klammer enthält.

Da das Problem auftaucht, wenn du FHEMWEB aufrufst, müßte es ein Gerät sein, das auf deiner Startseite angezeigt wird.

frank · 03 März 2023, 11:02:52

ZitatUnmatched ( in regex; marked by <-- HERE in m/^( <-- HERE most$/ at ./FHEM/01_FHEMWEB.pm line 3047.

ich würde sagen, der pfeil in der fehlermeldung zeigt nicht auf die klammer, sondern auf das leerzeichen rechts von der klammer. im code wird zunächst auch am leerzeichen gesplittet.
demnach suchst du nach einem leerzeichen, das dort verboten ist, wo es steht.

OiledAmoeba · 03 März 2023, 11:36:43

Ich glaube, ich habe es gefunden.
Hilfreich war es, die 01_FHEMWEB.pm so zu ändern:

Code Auswählen

3047 Log 1, "-----";
3048 Log 1, "$l:$iconName:$link::$devStateIcon";
3049 Log 1, "$re:$state";
3050       if(defined($re) && $state =~ m/^$re$/) {

In der aufgezeichneten Fehlermeldung ist der Fehler daher auch in Zeile 3050 gerutscht:

Code Auswählen

2023.03.03 10:56:10.160 1: -----
2023.03.03 10:56:10.161 1: Maybe::<img class=' 10px-kreis-gruen' src="/fhem/images/default/10px-kreis-gruen.png" alt="10px-kreis-gruen" title="10px-kreis-gruen">Module failed to load: tuya
Maybe you need to update fhempy on this or remote peer.

Stacktrace:
Traceback (most recent call last):
  File "/opt/fhem/.local/lib/python3.9/site-packages/fhempy/lib/fhem_pythonbinding.py", line 336, in handle_function
    module_object = await self.import_module(hash)
  File "/opt/fhem/.local/lib/python3.9/site-packages/fhempy/lib/fhem_pythonbinding.py", line 573, in import_module
    module_object = await utils.run_blocking(
  File "/opt/fhem/.local/lib/python3.9/site-packages/fhempy/lib/utils.py", line 72, in run_blocking
    return await asyncio.get_event_loop().run_in_executor(pool, function)
  File "/usr/lib/python3.9/concurrent/futures/thread.py", line 52, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/lib/python3.9/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
  File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 790, in exec_module
  File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
  File "/opt/fhem/.local/lib/python3.9/site-packages/fhempy/lib/tuya/tuya.py", line 8, in <module>
    import tinytuya as tt
  File "/opt/fhem/.local/lib/python3.9/site-packages/tinytuya/__init__.py", line 92, in <module>
    from .core import *
  File "/opt/fhem/.local/lib/python3.9/site-packages/tinytuya/core.py", line 67, in <module>
    from colorama import init
ModuleNotFoundError: No module named 'colorama'

2023.03.03 10:56:10.161 1: Maybe:Module failed to load: tuya
<Schnipp>
Wiederholung des Stacktrace für jedes Wort von "Maybe you need to update fhempy on this or remote peer."
</Schnipp>
2023.03.03 10:56:10.182 1: (most:Module failed to load: tuya
Unmatched ( in regex; marked by <-- HERE in m/^( <-- HERE most$/ at ./FHEM/01_FHEMWEB.pm line 3050.

Interessant war hier: ModuleNotFoundError: No module named 'colorama'
Mit pip3 install colorama nachinstalliert und seitdem kann ich wieder auf FHEMWEB zugreifen.

Ganz ehrlich? Keine Ahnung, was da passiert ist und warum er entweder plötzlich colorama brauchte oder es plötzlich weg war, aber scheinbar war das der Fehler...
Das einzige, was ich vor dem letzten Neustart relativ regelmäßig gemacht habe, war, dass ich dem fhempy_local ein "set update" spendiert habe. Vermutlich entstand hier irgendwann die Abhängigkeit zu colorama, was aber erst jetzt durch den Neustart aufgefallen ist.

Das ist das fhempy-Gerät:

Code Auswählen

define fhempy_local BindingsIo fhempy
attr fhempy_local DbLogExclude .*
attr fhempy_local devStateIcon {      my $attr_ver = "1.1.0";;;;      my $status_img = "10px-kreis-gruen";;;;      my $status_txt = "connected";;;;      my $ver = ReadingsVal($name, "version", "-");;;;      my $ver_available = ReadingsVal($name, "version_available", $ver);;;;      my $update_icon = "";;;;      my $refresh_img = "refresh";;;;      my $refresh_txt = "Update fhempy";;;;      if ($ver_available ne $ver) {        $refresh_img = "refresh\@orange";;;;        $refresh_txt = "Version ".$ver_available." available for update";;;;      }      if (ReadingsVal($name, "state", "disconnected") eq "disconnected") {        $status_img = "10px-kreis-rot";;;;        $status_txt = "disconnected";;;;      }      $update_icon = "<a  href=\"/fhem?cmd.dummy=set $name update&XHR=1\" title=\"Start ".$ver_available." update\">".FW_makeImage($refresh_img, $refresh_txt)."</a>";;;;      my $restart_icon = "<a  href=\"/fhem?cmd.dummy=set $name restart&XHR=1\" title=\"Restart fhempy\">".FW_makeImage("control_reboot")."</a>";;;;      "<div><a>".FW_makeImage($status_img, $status_txt)."</a><a> ".$ver." </a>".$update_icon.$restart_icon."</div>"    }
attr fhempy_local group fhempy
attr fhempy_local icon file_json-ld2
attr fhempy_local room fhempy
#   BindingType fhempy
#   DEF        fhempy
#   DeviceName ws:127.0.0.1:15733
#   FD         28
#   FUUID      63bac5e9-f33f-2b54-bb3e-82d15c411435f1ba
#   FVERSION   10_BindingsIo.pm:0.182830/2019-01-16
#   IP         127.0.0.1
#   NAME       fhempy_local
#   NR         803
#   NTFY_ORDER 50-fhempy_local
#   PARTIAL    
#   PORT       15733
#   STATE      opened
#   TYPE       BindingsIo
#   WEBSOCKET  1
#   binary     1
#   connecttime 1677839227.96291
#   devioLoglevel 0
#   eventCount 4
#   installing 0
#   localBinding 1
#   nextOpenDelay 10
#   prev_error read from http://127.0.0.1:15733 timed out
#   READINGS:
#     2023-03-03 01:36:26   hostname        fhem-rasp
#     2023-03-03 01:36:26   os              posix
#     2023-03-03 01:36:26   python          3.9.2
#     2023-03-03 01:36:26   release         5.15.76-v8+
#     2023-03-03 11:27:07   state           opened
#     2023-03-03 01:36:26   system          Linux
#     2023-03-03 01:36:26   version         0.1.613
#     2023-03-03 11:27:09   version_available 0.1.613
#     2023-03-03 11:27:09   version_release_notes <html><a href="https://github.com/fhempy/fhempy/releases" target="_blank">Release Notes</a></html>
#   args:
#     fhempy_local
#     BindingsIo
#     fhempy
#   messages:
... rausgenommen wegen Tuya-Keys ... 
#
setstate fhempy_local opened
setstate fhempy_local 2023-03-03 01:36:26 hostname fhem-rasp
setstate fhempy_local 2023-03-03 01:36:26 os posix
setstate fhempy_local 2023-03-03 01:36:26 python 3.9.2
setstate fhempy_local 2023-03-03 01:36:26 release 5.15.76-v8+
setstate fhempy_local 2023-03-03 11:27:07 state opened
setstate fhempy_local 2023-03-03 01:36:26 system Linux
setstate fhempy_local 2023-03-03 01:36:26 version 0.1.613
setstate fhempy_local 2023-03-03 11:27:09 version_available 0.1.613
setstate fhempy_local 2023-03-03 11:27:09 version_release_notes <html><a href="https://github.com/fhempy/fhempy/releases" target="_blank">Release Notes</a></html>

rudolfkoenig · 03 März 2023, 15:36:28

Die statische Variante des devStateIcons wurde bisher auch auf kaputte Regexps getestet, ab sofort wird das auch fuer die dynamisch erstellte Version gemacht.

OiledAmoeba · 03 März 2023, 23:07:54

Super, vielen Dank! Ich freue mich immer wieder, wie aktiv an diesem Projekt gearbeitet wird. Nicht nur Du, sondern alle Devs. Kaum fällt was auf, ist es schon behoben. Echt Klasse!

Ich hab mir das Log um den Absturz herum noch mal genauer angesehen. Das Problem war gar nicht mal, dass das Modul fehlte, sondern die Fehlermeldung dazu, bzw die Tatsache, dass die Prozedur den Stacktrace abgefangen hat. Die Prozedur hat dann den Text des Trace Wort für Wort verarbeitet und dann kam die Stelle, wo im Stacktrace die Vermutung kommt, die mit (most anfängt. Dadurch war dann plötzlich die öffnende Klammer in der Variable, die dann bei der Auswertung den Interpreter gekillt hat. Die schließende Klammer hätte es auch gegeben, aber durch die wortweise Auswertung kommt die halt erst in einem späteren Durchlauf.
Aber ich denke mal, dass Du genau diese Eventualität jetzt abfängst.
Noch mal ein dickes Danke für den Fix!