Nach Update Perl Fehlermeldung und Fhem down

[Ralli]

Guten Morgen,

bei mir auch. In meiner Installation wurden folgende Module erneuert:

Code Auswählen Erweitern


List of new / modified files since last update:
UPD ./CHANGED
UPD FHEM/00_FBAHA.pm
UPD FHEM/00_MQTT.pm
UPD FHEM/10_CUL_HM.pm
UPD FHEM/10_EQ3BT.pm
UPD FHEM/10_FBDECT.pm
UPD FHEM/10_MQTT_DEVICE.pm
UPD FHEM/10_ZWave.pm
UPD FHEM/14_CUL_TCM97001.pm
UPD FHEM/23_LUXTRONIK2.pm
UPD FHEM/30_DUOFERN.pm
UPD FHEM/49_SSCam.pm
UPD FHEM/72_FRITZBOX.pm
UPD FHEM/73_ElectricityCalculator.pm
UPD FHEM/73_GasCalculator.pm
UPD FHEM/73_WaterCalculator.pm
UPD FHEM/93_DbLog.pm
UPD FHEM/93_DbRep.pm
UPD FHEM/95_Babble.pm
UPD FHEM/98_DOIFtools.pm
UPD FHEM/98_GOOGLECAST.pm
UPD FHEM/98_SVG.pm
UPD FHEM/98_freezemon.pm
UPD FHEM/99_SUNRISE_EL.pm
UPD FHEM/HMConfig.pm
UPD contrib/commandref_join.pl
UPD www/pgm2/babble.js
UPD www/pgm2/f18.js


Leider gibt es bei mir im Log überhaupt keine Fehlermeldung, welche Komponente ein Problem verursacht. Fhem bleibt einfach hängen. Hier mal zur Gegenüberstellung:

Erfolgreicher Start:

Code Auswählen Erweitern


2018.02.26 11:20:17.844 1: Including fhem.cfg
2018.02.26 11:20:17.920 3: telnetPort: port 7072 opened
2018.02.26 11:20:18.817 3: WEB: port 8083 opened
2018.02.26 11:20:18.818 3: WEBphone: port 8084 opened
2018.02.26 11:20:18.818 3: WEBtablet: port 8085 opened
2018.02.26 11:20:18.987 2: eventTypes: loaded 3031 events from log/eventTypes.txt
2018.02.26 11:20:21.935 1: HMCCU: Device CCU2. Initialized version 4.2.002
2018.02.26 11:20:25.221 1: HMCCU: Read 110 devices with 482 channels from CCU 10.0.0.20
2018.02.26 11:20:25.221 1: HMCCU: Read 4 interfaces from CCU 10.0.0.20
2018.02.26 11:20:25.421 1: HMCCURPC: Device CCU2_rpc. Initialized version 1.0
2018.02.26 11:20:26.834 1: SONOS0: Modify Device: Sonos
2018.02.26 11:20:26.881 1: SONOS0: Modify SonosPlayer-Device: Sonos_Schlafzimmer
2018.02.26 11:20:26.976 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kind1
2018.02.26 11:20:26.978 1: SONOS0: Modify SonosPlayer-Device: Sonos_Esszimmer
2018.02.26 11:20:26.981 1: SONOS0: Modify SonosPlayer-Device: Sonos_Bad
2018.02.26 11:20:26.983 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kueche
2018.02.26 11:20:26.986 1: SONOS0: Modify SonosPlayer-Device: Sonos_HWR
2018.02.26 11:20:26.988 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kind2
2018.02.26 11:20:27.333 3: WZ_Lampe_Sub: I/O device is LIGHTIFY_GW
2018.02.26 11:20:27.334 3: LNA_Tischlampe: I/O device is LIGHTIFY_GW
2018.02.26 11:20:28.071 3: [STV] defined with host: 10.0.0.33 port: 55000 MAC: 00:0c:29:79:b1:12
2018.02.26 11:20:28.292 3: TelegramBot_Define Telegram: called
2018.02.26 11:20:29.071 3: LIGHTIFYGroup0: I/O device is LIGHTIFY_GW
2018.02.26 11:20:29.072 3: LIGHTIFYGroup1: I/O device is LIGHTIFY_GW
2018.02.26 11:20:29.074 3: LIGHTIFYGroup2: I/O device is LIGHTIFY_GW
2018.02.26 11:20:29.107 1: HMCCURPCPROC: [d_rpcBidCos_RF] Initialized version 1.0.002 for interface BidCos-RF
2018.02.26 11:20:29.108 1: HMCCURPCPROC: [d_rpcBidCos_Wired] Initialized version 1.0.002 for interface BidCos-Wired
2018.02.26 11:20:29.108 1: HMCCURPCPROC: [d_rpcHmIP_RF] Initialized version 1.0.002 for interface HmIP-RF
2018.02.26 11:20:29.109 1: Including ./log/fhem.save
2018.02.26 11:20:29.181 0: HMCCU: Start of RPC server after FHEM initialization in 12 seconds
2018.02.26 11:20:29.681 3: LIGHTIFY_GW: connected to 10.0.0.73
2018.02.26 11:20:29.685 0: Featurelevel: 5.8
2018.02.26 11:20:29.685 0: Server started with 284 defined entities (fhem.pl:16228/2018-02-20 perl:5.022001 os:linux user:fhem pid:1287)


Fehlerhafter Start:

Code Auswählen Erweitern


2018.02.26 11:16:14.871 1: Including fhem.cfg
2018.02.26 11:16:14.946 3: telnetPort: port 7072 opened
2018.02.26 11:16:16.239 3: WEB: port 8083 opened
2018.02.26 11:16:16.239 3: WEBphone: port 8084 opened
2018.02.26 11:16:16.240 3: WEBtablet: port 8085 opened
2018.02.26 11:16:16.461 2: eventTypes: loaded 3031 events from log/eventTypes.txt
2018.02.26 11:16:20.510 1: HMCCU: Device CCU2. Initialized version 4.2.002
2018.02.26 11:16:23.604 1: HMCCU: Read 110 devices with 482 channels from CCU 10.0.0.20
2018.02.26 11:16:23.604 1: HMCCU: Read 4 interfaces from CCU 10.0.0.20
2018.02.26 11:16:23.844 1: HMCCURPC: Device CCU2_rpc. Initialized version 1.0
2018.02.26 11:16:24.663 1: SONOS0: Modify Device: Sonos
2018.02.26 11:16:24.686 1: SONOS0: Modify SonosPlayer-Device: Sonos_Schlafzimmer
2018.02.26 11:16:24.750 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kind1
2018.02.26 11:16:24.752 1: SONOS0: Modify SonosPlayer-Device: Sonos_Esszimmer
2018.02.26 11:16:24.755 1: SONOS0: Modify SonosPlayer-Device: Sonos_Bad
2018.02.26 11:16:24.757 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kueche
2018.02.26 11:16:24.759 1: SONOS0: Modify SonosPlayer-Device: Sonos_HWR
2018.02.26 11:16:24.761 1: SONOS0: Modify SonosPlayer-Device: Sonos_Kind2
2018.02.26 11:16:25.009 3: WZ_Lampe_Sub: I/O device is LIGHTIFY_GW
2018.02.26 11:16:25.010 3: LNA_Tischlampe: I/O device is LIGHTIFY_GW
2018.02.26 11:16:25.410 3: [STV] defined with host: 10.0.0.33 port: 55000 MAC: 00:0c:29:79:b1:12
2018.02.26 11:16:25.690 3: TelegramBot_Define Telegram: called


[hanske]

Ok,
dann mache ich lieber erst mal kein Update.
Bisher stürzt FHEM ja "nur" ab und zu ab.
Welches DOIF das verursacht kann ich leider nicht sagen.
Vor einem halbe Jahr hatte ich eine reproduzierbare Zeile im DOIF, die das verursacht hat.
Die Zeile war aber komplett unauffällig.
Das DOIF war sehr lang mit ca. zehn DOELSEIFs und an die 30 Bedingungen.
Ich habe sie dann rausgeschmissen und baue jetzt lieber kleinere DOIFs.
Leider tritt der Fehler jetzt wieder auf, aber ich weiß nicht von wo.

Grüße
hanske

[Frank_Huber]

Aktuell ist es wohl das fritzbox Modul dass den Start verhindert.

Mit dem Handy online, daher kurz gefasst...

[Damian]

Hi,
ja klar, mache dann immer ein Restart.
Ich benutze folgende Version:

Code Auswählen Erweitern

98_DOIF.pm          16182 2018-02-14 21:36:04Z Damian
Ich habe inzwischen mehrmals täglich den Absturz durch ein DOIF.

Code Auswählen Erweitern

Modification of non-creatable array value attempted, subscript -1 at ./FHEM/98_DOIF.pm line 1906.
Ein cron job startet mir jetzt glücklicherweise FHEM dann wieder neu.
Kann ich irgendwie weiter analysieren, wenn man den Fehler nicht direkt im Sourcecode abfangen kann?

Danke und Grüße
hanske

Es müsste ein DOIF-Device sein, welches cmdpause benutzt.

Du kannst die angehängte Version testen.

[hanske]

cmdpause ist ein guter Hinweis, das benutze ich nur selten.
Ich kann mal gucken, ob ich es temporär abschalten kann.

[Damian]

cmdpause ist ein guter Hinweis, das benutze ich nur selten.
Ich kann mal gucken, ob ich es temporär abschalten kann.

Ich würde erst mal nur die gepatchte DOIF-Version drauf spielen und nichts an der Konfiguration ändern, damit ich weiß, ob das Problem damit behoben ist.

[Skusi]

Hallo,
seit nunmehr 4 Tagen komme ich nur noch zu spät ins Bett, weil sich Fhem immer zwischen 22 und 24 Uhr so aufhängt, das nicht mal ein reboot hilft. Der Fhem Prozess endet immer bei 100% CPU.
Um es kurz zumachen, habe ich gestern den Übeltäter finden können, und erstmal aus der cfg geschmissen.

Sobald folgendes DOIF im cfg steht, hängt sich Fhem genau um 23:15 auf.

Code Auswählen Erweitern

DEF        ([RollosOst] eq "closed")
(set WandTableau ttsSay Rolladen vorne sind nun zu)

DOELSEIF ([([Wecker] - [06:15])|01234] and [?Bubu] == 0 and [?Status] eq "Alltag")
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

DOELSE


Augenmerk also auf den DOELSEIF Teil. Das Ganze DOIF lief allerdings schon seit Monaten einwandfrei. Das Problem kann also erst nach dem letzten Update (Samstag) akut sein. Die Zeitberechnung [([Wecker] - [06:15])|01234] ist laut Commadref in Ordnung. Das Wecker Dummy hat den Wert 05:30. Außerdem kommt der Befehl derzeit nicht zur Ausführung weil [?Status] eq "Alltag" unwahr ist.

Bin Ratlos was ich machen soll. Ist es wirklich ein Bug im DOIF, und ich kann das nach einem Update wieder so einbauen ? Oder hat sich irgendwas geändert das solche Definitionen nicht mehr funktionieren. Liegt es am Zusammenspiel irgendwelcher Attribute ?

Hier nochmal die gesamte def:

Code Auswählen Erweitern

Internals:
   DEF        ([RollosOst] eq "closed")
(set WandTableau ttsSay Rolladen vorne sind nun zu)

DOELSEIF ([([Wecker] - [06:15])|01234] and [?Bubu] == 0 and [?Status] eq "Alltag")
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

DOELSE
   NAME       Sprachmeldung_Tableau
   NR         174
   NTFY_ORDER 50-Sprachmeldung_Tableau
   STATE      initialized
   TYPE       DOIF
   READINGS:
     2018-03-07 10:31:50   cmd             0
     2018-03-07 10:31:50   mode            enabled
     2018-03-07 10:31:50   state           initialized
     2018-03-07 10:31:50   timer_01_c02    07.03.2018 23:15:00|01234
   Regex:
   condition:
     0          InternalDoIf($hash,'RollosOst','STATE') eq "closed"
     1          DOIF_time_once($hash,0,$wday,"01234") and InternalDoIf($hash,'Bubu','STATE') == 0 and InternalDoIf($hash,'Status','STATE') eq "Alltag"
   days:
     0          01234
   devices:
     0           RollosOst
     all         RollosOst
   do:
     0:
       0          set WandTableau ttsSay Rolladen vorne sind nun zu
     1:
       0          set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !
     2:
       0         
   helper:
     DOIF_Readings_events
     DOIF_eventas
     globalinit 1
     last_timer 1
     sleeptimer -1
   internals:
     0           RollosOst:STATE
     1           Bubu:STATE Status:STATE
     all         RollosOst:STATE Bubu:STATE Status:STATE
   itimer:
     all         Wecker
   localtime:
     0          1520460900
   realtime:
     0          23:15:00
   time:
     0          ([Wecker]-[06:15])
   timeCond:
     0          1
   timer:
     0          0
   timers:
     1           0
   triggertime:
     1520460900:
       localtime  1520460900
       hash:
   uiState:
   uiTable:
Attributes:
   cmdpause   0:300
   group      Meldungen
   repeatsame 0:3
   room       9.0_System
   verbose    0

Wäre für eine Tip dankbar...

[betateilchen]

Die Zeitberechnung [([Wecker] - [06:15])|01234] ist laut Commadref in Ordnung. Das Wecker Dummy hat den Wert 05:30.

Wenn man von 06:15 Uhr bis 05:30 Uhr des nächsten Tages rechnet, kommen genau 23 Stunden und 15 Minuten raus.

Ist das Zufall?

Sobald folgendes DOIF im cfg steht, hängt sich Fhem genau um 23:15 auf.

Wohl eher nicht. Offenbar wird im vorliegenden Fall eine relative Zeitdauer in einen absoluten Zeitpunkt verwandelt.

[Damian]

Bei deiner Zeitberechnung kommt -00:45 heraus, das wird vom DOIF als 45 Minuten vor Mitternacht angesehen, daher 23:15. Du kannst versuchen das Problem weiter einzukreisen, in dem du die Definition abspeckst. Z. B.

(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

auskommentierst. Oder die gesetzten Attribute löschst.

Im DOIF hat sich nichts geändert, was auf das Problem hindeuten würde.

[Ellert]

Hallo,
seit nunmehr 4 Tagen komme ich nur noch zu spät ins Bett, weil sich Fhem immer zwischen 22 und 24 Uhr so aufhängt, das nicht mal ein reboot hilft. Der Fhem Prozess endet immer bei 100% CPU.
Um es kurz zumachen, habe ich gestern den Übeltäter finden können, und erstmal aus der cfg geschmissen.

Sobald folgendes DOIF im cfg steht, hängt sich Fhem genau um 23:15 auf.

Code Auswählen Erweitern

DEF        ([RollosOst] eq "closed")
(set WandTableau ttsSay Rolladen vorne sind nun zu)

DOELSEIF ([([Wecker] - [06:15])|01234] and [?Bubu] == 0 and [?Status] eq "Alltag")
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

DOELSE


Augenmerk also auf den DOELSEIF Teil. Das Ganze DOIF lief allerdings schon seit Monaten einwandfrei. Das Problem kann also erst nach dem letzten Update (Samstag) akut sein. Die Zeitberechnung [([Wecker] - [06:15])|01234] ist laut Commadref in Ordnung. Das Wecker Dummy hat den Wert 05:30. Außerdem kommt der Befehl derzeit nicht zur Ausführung weil [?Status] eq "Alltag" unwahr ist.

Bin Ratlos was ich machen soll. Ist es wirklich ein Bug im DOIF, und ich kann das nach einem Update wieder so einbauen ? Oder hat sich irgendwas geändert das solche Definitionen nicht mehr funktionieren. Liegt es am Zusammenspiel irgendwelcher Attribute ?

Hier nochmal die gesamte def:

Code Auswählen Erweitern

Internals:
   DEF        ([RollosOst] eq "closed")
(set WandTableau ttsSay Rolladen vorne sind nun zu)

DOELSEIF ([([Wecker] - [06:15])|01234] and [?Bubu] == 0 and [?Status] eq "Alltag")
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

DOELSE
   NAME       Sprachmeldung_Tableau
   NR         174
   NTFY_ORDER 50-Sprachmeldung_Tableau
   STATE      initialized
   TYPE       DOIF
   READINGS:
     2018-03-07 10:31:50   cmd             0
     2018-03-07 10:31:50   mode            enabled
     2018-03-07 10:31:50   state           initialized
     2018-03-07 10:31:50   timer_01_c02    07.03.2018 23:15:00|01234
   Regex:
   condition:
     0          InternalDoIf($hash,'RollosOst','STATE') eq "closed"
     1          DOIF_time_once($hash,0,$wday,"01234") and InternalDoIf($hash,'Bubu','STATE') == 0 and InternalDoIf($hash,'Status','STATE') eq "Alltag"
   days:
     0          01234
   devices:
     0           RollosOst
     all         RollosOst
   do:
     0:
       0          set WandTableau ttsSay Rolladen vorne sind nun zu
     1:
       0          set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !
     2:
       0         
   helper:
     DOIF_Readings_events
     DOIF_eventas
     globalinit 1
     last_timer 1
     sleeptimer -1
   internals:
     0           RollosOst:STATE
     1           Bubu:STATE Status:STATE
     all         RollosOst:STATE Bubu:STATE Status:STATE
   itimer:
     all         Wecker
   localtime:
     0          1520460900
   realtime:
     0          23:15:00
   time:
     0          ([Wecker]-[06:15])
   timeCond:
     0          1
   timer:
     0          0
   timers:
     1           0
   triggertime:
     1520460900:
       localtime  1520460900
       hash:
   uiState:
   uiTable:
Attributes:
   cmdpause   0:300
   group      Meldungen
   repeatsame 0:3
   room       9.0_System
   verbose    0

Wäre für eine Tip dankbar...

Dann ersetze die Befehle

Code Auswählen Erweitern

(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)
durch einen Log-Befehl

Code Auswählen Erweitern

{Log 1, "DOIF Test"}

Wenn es dann keine Probleme gibt, könnte es mit einem Befehl zusammenhängen.

[Skusi]

Das bei meiner Berechnung 23:15 als Zeitpunkt herauskommt ist mir klar, und auch so gewollt.

Code Auswählen Erweitern

(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)

Wenn ich diese Befehle manuel absetze werden sie einwnadfrei ausgeführt. Also kann ich mir nicht denken das das auskommentieren den Absturz verhindert.

...

[Damian]

Das Attribut repeatsame macht nur Sinn wenn ein zyklischer Trigger da wäre, du hast aber nur einen um 23:15.
Hier wäre die Kombination mit repeatcmd statt cmdpause sinnvoll.

Allerdings würde ich zunächst alle Attribute löschen, um ein Fehlverhalten auszuschließen.

[Skusi]

Juhu ! Gestern konnte ich einfach mal ohne lange Sitzung am Notebook zu Bett gehen.

Nachdem ich also nun den DOELSEIF Teil raus genommen und alle Attribute gelöscht habe, gab es keinen Absturz mehr.

OK, aber nun interessiert mich immer noch die eigentliche Ursache des Ganzen. Hab ich jetzt den Fehler verursacht, oder hat sich in Fhem irgendwas geändert das dieses Verhalten ausgelöst hat ?

Nun habe ich eben den bösen Teil testweise wieder eingefügt und die Berechnung so modifiziert das der Trigger Zeitpunk zeitnah liegt.

Code Auswählen Erweitern

DOELSEIF ([([Wecker] - [17:15])|01234] and [?Bubu] == 0 and [?Status] ne "Alltag") \
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)\

Keine Attr gesetzt !

Trigger Zeitpunkt liegt nun bei "Wecker" = 03:00 um 9:45. Was soll ich sagen: Fhem hängt bei 100% CPU und nix geht mehr.
Das kann doch nur an der Zeitberechnung liegen die über die Mitternachtsgrenze geht. Ich habe noch in anderen DOIFs solche Rechnungen die einwandfrei funktionieren. Aber keine von denen geht rückwärts in den negativen Bereich.
Ist da im DOIF Modul irgendwas schief das das nicht funktioniert ? Ich kann mir das nicht anders erklären. Vor allem vor dem Hintergrund das ich dieses DOIF ewig nicht angefasst hatte und nun seit Samstag bringt es das gesamte System zum stehen.

[Damian]

Juhu ! Gestern konnte ich einfach mal ohne lange Sitzung am Notebook zu Bett gehen.

Nachdem ich also nun den DOELSEIF Teil raus genommen und alle Attribute gelöscht habe, gab es keinen Absturz mehr.

OK, aber nun interessiert mich immer noch die eigentliche Ursache des Ganzen. Hab ich jetzt den Fehler verursacht, oder hat sich in Fhem irgendwas geändert das dieses Verhalten ausgelöst hat ?

Nun habe ich eben den bösen Teil testweise wieder eingefügt und die Berechnung so modifiziert das der Trigger Zeitpunk zeitnah liegt.

Code Auswählen Erweitern

DOELSEIF ([([Wecker] - [17:15])|01234] and [?Bubu] == 0 and [?Status] ne "Alltag") \
(set WandTableau audioPlay /Audio/soft-bells.mp3, set Gigablue msg message 5 Nun aber ins Bett !)\

Keine Attr gesetzt !

Trigger Zeitpunkt liegt nun bei "Wecker" = 03:00 um 9:45. Was soll ich sagen: Fhem hängt bei 100% CPU und nix geht mehr.
Das kann doch nur an der Zeitberechnung liegen die über die Mitternachtsgrenze geht. Ich habe noch in anderen DOIFs solche Rechnungen die einwandfrei funktionieren. Aber keine von denen geht rückwärts in den negativen Bereich.
Ist da im DOIF Modul irgendwas schief das das nicht funktioniert ? Ich kann mir das nicht anders erklären. Vor allem vor dem Hintergrund das ich dieses DOIF ewig nicht angefasst hatte und nun seit Samstag bringt es das gesamte System zum stehen.

Also die Zeitberechnung ergibt zumindest eine sinnvolle Triggerzeit, siehe Timer-Readings. Wenn du irgendwo Wecker veränderst, dann wird jedes mal DOIF getriggert und führt eine Neuberechnung der Zeit durch. Vielleicht hast du dir da irgendwo ein Loop eingebaut.

[Skusi]

Versteh ich nicht

Das hier funkt doch auch:

Code Auswählen Erweitern

([([Wecker]+[00:15])|8])
(set Kaffeemaschine on-for-timer 900)

Außerdem stürzt Fhem ja nicht ab wenn ich Wecker verändere und das DOIF die triggertime neu setzt, sondern erst wenn der trigger aktiv wird.

Ich sehe da den loop nicht heraus.