Seit kurzem habe ich ein Problem mit at devices, die wiederholt ausgeführt werden sollen.
define at_heartbeat at +*00:01:00 {qx(touch /opt/fhem/log/fhem.heartbeat)}
attr at_heartbeat alignTime 00:01
Das funktioniert eine Zeitlang hervorragend, irgendwann stellt das at aber einfach seinen Dienst ein.
Klicke ich dann im Frontende das DEF an und speichere es über den zugehörigen Button unter dem Editorfenster wieder ab, wird die Ausführung wieder für eine gewisse Zeit fortgesetzt.
Kann das irgendwie mit den Änderungen an 90_at.pm zusammenhängen, die in den vergangenen Tagen erfolgt sind?
Seit 5.8 ist perlSyntaxCheck aktiviert. Bis vorgestern wurde diese Funktion bei jeder at-definition (was nach jeder at Ausfuehrung automatisch wiederholt wird) auch mit ausgefuehrt. Ich wuesste zwar nicht, wieso das nur in manchen Faellen ein Problem sein sollte, aber wenn ja, dann wuerde das dein Problem erklaeren.
Ich werde perlSyntaxCheck testweise abschalten.
Apropos perlSyntaxCheck: könntest Du bei Gelegenheit die Werteliste zum Attribut noch in FHEM hinterlegen?
Ich habe ein at, welches alle 15 Sekunden ausgeführt wird. Seit dem Update ist es in einem Loop. Soll heißen, es wird so oft ausgeführt wie nur möglich (hunderte Male pro Sekunde).
Danke für den Hinweis zum perlSyntaxCheck, werde ich auch mal versuchen.
Also am perlSyntaxCheck liegt es nicht, den hab ich abgeschaltet. Mein at hängt seit gestern Abend 21:36 schon wieder.
FHEM wurde um 21:35 neugestartet, nach dem Neustart wird das at nicht mehr ausgeführt.
2017.02.26 21:35:53 0: Server shutdown
2017.02.26 21:36:04 3: telnetPort: port 7072 opened
2017.02.26 21:36:05 3: web: port 8083 opened
2017.02.26 21:36:08 0: Featurelevel: 5.8
2017.02.26 21:36:08 0: Server started with 8 defined entities (fhem.pl:13532/2017-02-26 perl:5.020002 os:linux user:fhem pid:16406)
Nach einem Klick auf "DEF" und "modify" läuft das at wieder.
Ich werde mir jetzt mal eine alte Modulversion von at besorgen. So kann ich at nicht gebrauchen.
Der Fehler ist auf meinem Test-FHEM beliebig reproduzierbar.
Nach einem FHEM restart wird das at nicht mehr neu gestartet.
fhem.pl 13532 2017-02-26 17:04:14Z rudolfkoenig
90_at.pm 13500 2017-02-24 09:12:38Z rudolfkoenig
Edit: mit #12717 scheint alles wieder wie gewünscht zu funktionieren.
Zitat von: betateilchen am 27 Februar 2017, 09:22:22
Edit: mit #12717 scheint alles wieder wie gewünscht zu funktionieren.
Zu früh gefreut. Geht auch damit nicht dauerhaft.
Im Logfile nichts auffälliges:
2017.02.27 09:38:32 5: Cmd: >define at_heartbeat at +*00:01:00 {qx(touch /opt/fhem/log/fhem.heartbeat)}<
2017.02.27 09:38:32 5: Loading ./FHEM/90_at.pm
2017.02.27 09:38:33 5: Cmd: >attr at_heartbeat alignTime 00:01<
2017.02.27 09:38:33 5: Cmd: >attr at_heartbeat group 50 Maintenance<
2017.02.27 09:38:33 5: Cmd: >attr at_heartbeat icon hourglass<
2017.02.27 09:38:33 5: Cmd: >attr at_heartbeat room 99 System<
Vielleicht hilft es bei der Fehlereingrenzung:
Lösche ich das Attribut alignTime, rennt das at nach einem (re)start wie gewünscht los.
Ich beobachte das gleiche Verhalten (siehe hier: https://forum.fhem.de/index.php/topic,67942.0.html (https://forum.fhem.de/index.php/topic,67942.0.html)), habe aber das Attribut alignTime bei meinen ats gar nicht gesetzt.
Ich kann das Problem nicht nachstellen. Ich habe beteteilchens at mit 10s konfiguriert, und der tickt hier seit mehreren Stunden und mehreren "shutdown restarts". Auch ein FHEMWEB modify (DEF bzw. Wizard probiert) bringt ihn nicht aus der Ruhe.
Nach etwas Nachdenken kann ich nur ein anderes Modul vorstellen, der %intAt direkt manipuliert (wieso greifen so viele Module darauf ueberhaupt zu???) oder mit RemoveInternalTimer den at Eintrag loescht.
Mit folgenden Ausdruecken kann man die intAt "Liste" ausgeben:
fhem> { map { Log 1, "$intAt{$_}{TRIGGERTIME}=>$intAt{$_}{FN}" } sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt }
fhem> { use Data::Dumper;; map { Log 1, "$intAt{$_}{TRIGGERTIME}=>$intAt{$_}{FN}" } sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt }
evtl. hilt das beim lokalisieren des Problems.
Habe ich mal gemacht und erhalte für beide Zeilen "6" zurück. Was fange ich jetzt damit an?
Zitat von: rudolfkoenig am 27 Februar 2017, 12:02:02
Ich kann das Problem nicht nachstellen. Ich habe beteteilchens at mit 10s konfiguriert, und der tickt hier seit mehreren Stunden und mehreren "shutdown restarts". Auch ein FHEMWEB modify (DEF bzw. Wizard probiert) bringt ihn nicht aus der Ruhe.
Nach etwas Nachdenken kann ich nur ein anderes Modul vorstellen, der %intAt direkt manipuliert (wieso greifen so viele Module darauf ueberhaupt zu???) oder mit RemoveInternalTimer den at Eintrag loescht.
Mit folgenden Ausdruecken kann man die intAt "Liste" ausgeben:
fhem> { map { Log 1, "$intAt{$_}{TRIGGERTIME}=>$intAt{$_}{FN}" } sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt }
fhem> { use Data::Dumper;; map { Log 1, "$intAt{$_}{TRIGGERTIME}=>$intAt{$_}{FN}" } sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt }
evtl. hilt das beim lokalisieren des Problems.
Hallo Rudi,
Ich entschuldige mich schon mal im Voraus weil mein Zwischenfragen bisschen unverschämt ist. Aber es passt gerade so gut.
Ist es eigentlich Notwendig ein RemoveInternalTimer in der Zeitverzögerten aufgerufenen Funktion zu machen wenn der Timer eh schon abgelaufen ist?
Danke Dir
Und noch mal Sorry
@JWRu: bitte ins FHEM-Logfile schauen.
@CoolTux: RemoveInternalTimer ist nicht notwendig, der Eintrag wird nach dem Aufruf entfernt. Wenn es nicht entfernt waere, wuerde die spezifizierte Funktion in einer (sehr aufwendigen) Endlosschleife aufgerufen.
Zitat von: rudolfkoenig am 27 Februar 2017, 12:02:02
Ich kann das Problem nicht nachstellen. Ich habe beteteilchens at mit 10s konfiguriert, und der tickt hier seit mehreren Stunden und mehreren "shutdown restarts". Auch ein FHEMWEB modify (DEF bzw. Wizard probiert) bringt ihn nicht aus der Ruhe.
Das Problem tritt bei mir auch nicht in allen FHEM Installationen auf. Interessanterweise ausgerechnet aber in der mit den wenigsten devices.
Fhem info:
Release : 5.8 FeatureLevel: 5.8
OS : linux
Arch : arm-linux-gnueabihf-thread-multi-64int
Perl : v5.20.2
uniqueID : cab637ee0a494784835e71491e440e3b
upTime : 03:48:17
Defined modules:
FHEMWEB : 1
FileLog : 1
at : 1
cmdalias : 1
configDB : 1
notify : 2
telnet : 1
Zitat von: rudolfkoenig am 27 Februar 2017, 12:02:02
Mit folgenden Ausdruecken kann man die intAt "Liste" ausgeben:
liefert bei mir:
2017.02.27 13:47:47 1: 1488199702=>FW_closeInactiveClients
2017.02.27 13:47:47 1: 1488199702.01774=>at_Exec
2017.02.27 13:47:47 1: 1488236401=>FileLog_dailySwitch
Zitat von: rudolfkoenig am 27 Februar 2017, 13:45:57
@CoolTux: RemoveInternalTimer ist nicht notwendig, der Eintrag wird nach dem Aufruf entfernt. Wenn es nicht entfernt waere, wuerde die spezifizierte Funktion in einer (sehr aufwendigen) Endlosschleife aufgerufen.
Ich bedanke mich ganz herzlich. Dann werde ich die nächsten Tage mal bisschen was gerade ziehen bei meinen Modulen. Muss ja nicht sein das sie als schlechtes Vorbild dienen. ;D
@betateilchen: die Ausgabe ist normal. Ich vermute, dass im Probemfall at_Exec fehlt.
Beide Zeilen liefert bei mir:
2017.02.27 14:17:32 1: 0=>CODE(0x26b3f38)
2017.02.27 14:17:32 1: 0=>CODE(0x26c3f80)
2017.02.27 14:17:32 1: 0=>CODE(0x2209708)
2017.02.27 14:17:32 1: 0=>CODE(0x26972c0)
2017.02.27 14:17:32 1: 1488186900=>FW_closeInactiveClients
2017.02.27 14:17:32 1: 1488215784=>at_Exec
2017.02.27 14:17:32 1: 1488232800=>at_Exec
2017.02.27 14:17:32 1: 1488236401=>FileLog_dailySwitch
Allerdings habe ich heute Vormittag für beide ats die def nochmal gespeichert, also müssten sie nach meinen bisherigen Erfahrungen heute Abend ausgeführt werden.
Kannst du bitte die Ergebnisse der zweiten Zeile auch zeigen?
Es kommt haargenau das gleiche, darum hatte ich es nicht gepostet:
2017.02.27 14:20:01 1: 0=>CODE(0x26b3f38)
2017.02.27 14:20:01 1: 0=>CODE(0x26c3f80)
2017.02.27 14:20:01 1: 0=>CODE(0x2209708)
2017.02.27 14:20:01 1: 0=>CODE(0x26972c0)
2017.02.27 14:20:01 1: 1488186900=>FW_closeInactiveClients
2017.02.27 14:20:01 1: 1488215784=>at_Exec
2017.02.27 14:20:01 1: 1488232800=>at_Exec
2017.02.27 14:20:01 1: 1488236401=>FileLog_dailySwitch
Sorry, habe die falsche Zeile geportet, es sollte heissen:
{ use Data::Dumper;; map { Log 1, $intAt{$_}{TRIGGERTIME}."=>".Dumper($intAt{$_}{ARG}) } sort { $intAt{$a}{TRIGGERTIME} <=> $intAt{$b}{TRIGGERTIME} } keys %intAt }
Die 4 Zeilen am Anfang sind nicht richtig: de muessten eine Endlosschleife verursachen.
Mit der korrigierten Zeile erhalte ich das:
2017.02.27 15:47:34 1: 1488206882=>$VAR1 = 0;
2017.02.27 15:47:34 1: 1488215784=>$VAR1 = {
'RELATIVE' => 'no',
'DEF' => '*{sunset(-1200,"16:00","22:30")} set Gartenbeleuchtung on',
'COMMAND' => 'set Gartenbeleuchtung on',
'REP' => -1,
'READINGS' => {
'state' => {
'TIME' => '2017-02-27 12:12:56',
'VAL' => 'Next: 18:16:24'
}
},
'PERIODIC' => 'yes',
'TYPE' => 'at',
'TRIGGERTIME_FMT' => '2017-02-27 18:16:24',
'TIMESPEC' => '{sunset(-1200,"16:00","22:30")}',
'NAME' => 'Gartenbeleuchtung_an',
'NR' => 34,
'NTM' => '18:16:24',
'TRIGGERTIME' => 1488215784,
'STATE' => 'Next: 18:16:24'
};
2017.02.27 15:47:34 1: 1488232800=>$VAR1 = {
'TRIGGERTIME' => 1488232800,
'STATE' => 'Next: 23:00:00',
'NAME' => 'Gartenbeleuchtung_aus',
'NR' => 35,
'TRIGGERTIME_FMT' => '2017-02-27 23:00:00',
'TIMESPEC' => '23:00',
'PERIODIC' => 'yes',
'TYPE' => 'at',
'READINGS' => {
'state' => {
'VAL' => 'Next: 23:00:00',
'TIME' => '2017-02-27 12:13:08'
}
},
'COMMAND' => 'set Gartenbeleuchtung off',
'REP' => -1,
'RELATIVE' => 'no',
'DEF' => '*23:00 set Gartenbeleuchtung off'
};
2017.02.27 15:47:34 1: 1488236401=>$VAR1 = {
'ORDER' => '92',
'NotifyFn' => 'FileLog_Log',
'DefFn' => 'FileLog_Define',
'SetFn' => 'FileLog_Set',
'FW_summaryFn' => 'FileLog_fhemwebFn',
'LOADED' => 1,
'SVG_sampleDataFn' => 'FileLog_sampleDataFn',
'SVG_regexpFn' => 'FileLog_regexpFn',
'FW_detailFn' => 'FileLog_fhemwebFn',
'AttrFn' => 'FileLog_Attr',
'AttrList' => 'addStateEvent:0,1 archiveCompress archivecmd archivedir createGluedFile:0,1 disable:0,1 disabledForIntervals eventOnThreshold logtype mseclog:1,0 nrarchive reformatFn',
'GetFn' => 'FileLog_Get',
'UndefFn' => 'FileLog_Undef'
};
Ich habe allerdings zwischenzeitlich TelegramBot eingerichtet - die entsprechenden Zeilen habe ich weggelassen (da tauchen UserID, token etc. im Klartext auf ;))
Woher die Endlosschleife kommt, weiß der Himmel.
Schaut alles friedlich aus. Sicherheitshalber "attr Gartenbeleuchtung.* verbose 5" ausfuehren, und warten, bis was schiefgeht. Dann im Log schauen, bzw. diese Zeilen wiederholen.
Ich habe das fehlerhafte at jetzt aus meiner Konfiguration gelöscht und identisch wieder neu angelegt.
Seither funktioniert das device, wie es soll.
Kann es irgendein Reihenfolge-Problem beim FHEM-Start geben, die dazu führen kann, dass ein at nicht korrekt arbeitet?
Die Tatsache, dass es nach einem defmod oder durch ein spätes Anlegen per notify auf global:INITIALIZED immer funktioniert hat, bringt mich zu der Vermutung.
Ich kann es mir nur vorstellen, dass irgendetwas, was nach dem at drankommt, den Eintrag aus %intAt entfernt. Also nicht at selbst ist schuld, sondern etwas anderes.
Aber bei den 8 devices, die ich oben aufgelistet hatte, ist doch nichts dabei, was so ein Verhalten an den Tag legt.
Defined modules:
FHEMWEB : 1
FileLog : 1
at : 1
cmdalias : 1
configDB : 1
notify : 2
telnet : 1
Das waere schonmal deswegen tragisch, weil ich fuer alle Module bis auf configDB verantwortlich bin, d.h. mit 87.5% wahrscheinlichkeit der Verursacher bin... :(
-> Will sagen: habe keine Idee.
Zitat von: rudolfkoenig am 27 Februar 2017, 18:48:52
weil ich fuer alle Module bis auf configDB verantwortlich bin,
Für configDB bin ich verantworlich und ich kann sagen, dass configDB sich nicht für %intAt interessiert.
Es ist also ein FHEM-Mysterium :)
Mein Endlos-at hatte ich vorgestern Abend deaktiviert (set ... inactive) und habe es gestern Abend wieder aktiviert (set ... active). Seit gestern Abend macht es genau das, was es soll: es wird alle 15 Sekunden ausgeführt. Auch nach einem Fhem-Neustart kann ich die von mir beschriebene Endlosschleife nicht mehr beobachten.
Das set inactive/active hatte ich auch vorgestern Abend versucht. Da blieb es jedoch bei der Endlosschleife.
Habe jetzt auf meinen anderen zwei Fhem-Instanzen, wo das gleiche at definiert ist, ein Update durchgeführt und neugestartet. Keine Endlosschleife. Die ats werden alle 15 Sekunden ausgeführt.
Ich werde das weiter beobachten und falls ich noch etwas dazu beitragen kann, mich wieder melden.
Auch bei mir sind die ats gestern und heute problemlos ausgeführt worden.
Hallo zusammen,
endlich mal ein Thread der auch meine Probleme beschreibt.
Seit einigen Tagen bleiben meine at's auch immer nach einiger Zeit unvermittelt stehen.
define Rolladen_morgens at *{twilight("Kaarst","sr","6:40","9:00")} { if (!($we)) { fhem("set EIB_1203 Hoch");;;; } }
Eine manuelle Aktion z.B. mit einem:
define temp twilight 51.2337962 6.6229446 1 664340;delete temp
stößt das System wieder für einen zufälligen Zeitraum an.
Ich bin am verzweifeln .....
Für das Problem gibt es inzwischen einen Fix, der morgen per update verteilt wird. Danach sollte das Problem gelöst sein.
Bis dahin hilft vielleicht folgender Workaround: "define blablub dummy" und ein Speichern der Konfiguration.
Damit ist auf jeden Fall kein at und kein notify das "letzte" definierte device in Deinem FHEM und die at sollten funktionieren. (Eventuell ist ein shutdown restart notwendig)
Super vielen Dank für die Korrektur!
Es scheint wieder alles OK.
Wo lag denn das Problem? ......
https://forum.fhem.de/index.php/topic,68383.0.html
Mahlzeit!
Zitat von: betateilchen am 26 Februar 2017, 17:22:12
define at_heartbeat at +*00:01:00 {qx(touch /opt/fhem/log/fhem.heartbeat)}
attr at_heartbeat alignTime 00:01
Da das Problem gefixt ist eine kurze Frage zur Befriedigung meiner Neugierde: Was genau treibst Du mit dem Heartbeat? Hast Du ein HA-Setup gebaut oder monitorst Du den Timestamp mit Nagios etc?
Patrick
Zitat von: PatrickR am 05 April 2017, 21:30:16
Mahlzeit!
Da das Problem gefixt ist eine kurze Frage zur Befriedigung meiner Neugierde: Was genau treibst Du mit dem Heartbeat? Hast Du ein HA-Setup gebaut oder monitorst Du den Timestamp mit Nagios etc?
Patrick
Wenn ich mich recht entsinne dann überwacht ein watchdog (linux anwendung) die Datei und wenn sie längere Zeit nicht beschrieben wurde wird FHEM neu gestartet.
Hi!
Zitat von: CoolTux am 05 April 2017, 21:46:49
Wenn ich mich recht entsinne dann überwacht ein watchdog (linux anwendung) die Datei und wenn sie längere Zeit nicht beschrieben wurde wird FHEM neu gestartet.
Danke für die Info. Habe das jetzt mal in Icinga integriert.
Patrick