Moin,
da es bei mir öfter vor kam, dass PRESENCE "gehangen" hat, bin ich dazu übergegangen die devices mit der hier https://forum.fhem.de/index.php/topic,15173.msg261574.html#msg261574 geklauten Routine zu überwachen. Nach 15 Minuten ohne state Änderung wird ein shutdown restart abgesetzt. Heute musste ich aber feststellen, dass der Zustand vom device dies überlebt und fhem in einen restart loop gerät :-( Ich habe mir ein betroffenes device dann mal genauer angesehen:
Statusrequest ergab dann another check is currently running
List auf device:
Internals:
ADDRESS 192.168.n.n
CFGFN
DEF lan-ping 192.168.n.n 20 150
MODE lan-ping
NAME Viera_WZ
NOTIFYDEV global
NR 654
NTFY_ORDER 50-Viera_WZ
STATE absent
TIMEOUT_NORMAL 20
TIMEOUT_PRESENT 150
TYPE PRESENCE
READINGS:
2017-07-13 12:25:28 presence absent
2017-07-13 12:25:28 state absent
helper:
ABSENT_COUNT 7
PRESENT_COUNT 0
RUNNING_PID:
abortFn PRESENCE_ProcessAbortedScan
arg Viera_WZ|192.168.n.n|0|4
bc_pid 18
finishFn PRESENCE_ProcessLocalScan
fn PRESENCE_DoLocalPingScan
pid DEAD:11654
timeout 60
abortArg:
Attributes:
absenceThreshold 8
event-on-change-reading state
okay, schein wohl ein ping Prozess beim restart hängen geblieben zu sein. Also reboot tut gut....
Device ist weiterhin absent und statusrequest ergibt auch wieder another check is currently running
verbose auf 5:
Internals:
ADDRESS 192.168.n.n
CFGFN
DEF lan-ping 192.168.n.n 20 150
MODE lan-ping
NAME Viera_WZ
NOTIFYDEV global
NR 654
NTFY_ORDER 50-Viera_WZ
STATE absent
TIMEOUT_NORMAL 20
TIMEOUT_PRESENT 150
TYPE PRESENCE
READINGS:
2017-07-13 12:25:28 presence absent
2017-07-13 12:25:28 state absent
helper:
ABSENT_COUNT 7
PRESENT_COUNT 0
RUNNING_PID:
abortFn PRESENCE_ProcessAbortedScan
arg Viera_WZ|192.168.n.n|0|4
bc_pid 18
finishFn PRESENCE_ProcessLocalScan
fn PRESENCE_DoLocalPingScan
pid DEAD:1660
timeout 60
abortArg:
Attributes:
absenceThreshold 8
event-on-change-reading state
verbose 5
Keinerlei Meldungen im LOG!?
Jemand eine Idee???
Nachtrag:
ein setreading state "weckt" PRESENCE mal kurz:
2017.07.13 18:18:47 5: PRESENCE (Viera_WZ) - starting local scan
2017.07.13 18:18:47 4: PRESENCE (Viera_WZ) - another check is currently running. skipping check
ein weiterer shutdown -r now brachte dann endlich das Modul wieder zum laufen.
Gruß
Arthur
Bin ich wirklich der Einzige mit diesem Problem????
Mir ist kein Fall bekannt, wo bei diesem Problem keinerlei weiterführende Logmeldungen im Log zu finden sind.
Dieses Problem tritt bspw. auf, wenn zu wenig freier RAM-Speicher vorhanden ist, um einen Fork vom Hauptprozess zu erstellen. Da steht dann aber auch immer eine Fehlermeldung im Log wie "cannot fork: unable to allocate memory"
Ein abgebrochener BlockingCall zieht eigentlich immer eine Fehlermeldung im Log mit sich.
Alternativ mal das verbose-Level global auf 5 setzen, aber da kommt dann eine ganze Menge im Log.
Ist denn das Probelm seit dem 13.07. wieder aufgetreten?
Gruß
Markus
Hallo Markus,
das Problem habe ich ständig, meist die selben devices. Z.B.
Internals:
ADDRESS 192.168.2.106
CFGFN
DEF lan-ping 192.168.2.106 60 300
MODE lan-ping
NAME Wifilight4
NOTIFYDEV global
NR 734
NTFY_ORDER 50-Wifilight4
STATE absent
TIMEOUT_NORMAL 60
TIMEOUT_PRESENT 300
TYPE PRESENCE
READINGS:
2017-07-26 04:00:32 model lan-ping
2017-07-25 03:59:45 presence absent
2017-07-25 03:59:45 state absent
helper:
ABSENT_COUNT 4
PRESENT_COUNT 0
RUNNING_PID:
abortFn PRESENCE_ProcessAbortedScan
arg Wifilight4|192.168.2.106|0|4
bc_pid 19
finishFn PRESENCE_ProcessLocalScan
fn PRESENCE_DoLocalPingScan
pid DEAD:22489
timeout 60
abortArg:
Attributes:
absenceThreshold 5
event-on-change-reading state
room LED
verbose 5
Manchmal lässt es sich durch einen restart, manchmal durch reboot beheben.
FHEM läuft auf einem Raspi 3, RAM sollte kein Problem sein.
MemTotal: 994232 kB
MemFree: 393108 kB
MemAvailable: 617376 kB
Ich hab jetzt mal ein device auf verbose=5 gesetzt und werde beobachten.
Gruß
Arthur
z.B. gestern Abend:
2017.07.26 21:17:53 5: PRESENCE (Wifilight4) - starting ping scan: Wifilight4|192.168.2.106|0|4
....
2017.07.26 21:17:59 5: PRESENCE (Wifilight4) - ping command returned with output:
PING 192.168.2.106 (192.168.2.106) 56(84) bytes of data.
From 192.168.2.140 icmp_seq=1 Destination Host Unreachable
From 192.168.2.140 icmp_seq=2 Destination Host Unreachable
From 192.168.2.140 icmp_seq=3 Destination Host Unreachable
From 192.168.2.140 icmp_seq=4 Destination Host Unreachable
--- 192.168.2.106 ping statistics ---
4 packets transmitted, 0 received, +4 errors, 100% packet loss, time 3118ms
pipe 4
Die nächste Meldung kommt dann von meinem device monitor:
2017.07.26 21:35:26 3: WARNING Wifilight4_Timeout error!
dann ist Ruhe.... bis
2017.07.26 22:57:45 5: PRESENCE (Wifilight4) - starting local scan
2017.07.26 22:57:45 4: PRESENCE (Wifilight4) - another check is currently running. skipping check
Um 4 Uhr kommt shutdown restart. Danach:
2017.07.27 04:01:47 5: PRESENCE (Wifilight4) - stopping timer
2017.07.27 04:01:47 5: PRESENCE (Wifilight4) - starting blocking call for mode lan-ping
...
2017.07.27 04:02:38 5: PRESENCE (Wifilight4) - starting ping scan: Wifilight4|192.168.2.106|0|4
2017.07.27 04:02:41 5: PRESENCE (Wifilight4) - ping command returned with output:
PING 192.168.2.106 (192.168.2.106) 56(84) bytes of data.
From 192.168.2.140 icmp_seq=1 Destination Host Unreachable
From 192.168.2.140 icmp_seq=2 Destination Host Unreachable
From 192.168.2.140 icmp_seq=3 Destination Host Unreachable
From 192.168.2.140 icmp_seq=4 Destination Host Unreachable
--- 192.168.2.106 ping statistics ---
4 packets transmitted, 0 received, +4 errors, 100% packet loss, time 3064ms
pipe 4
Um 7 Uhr merkt dann der device monitor das kein update mehr war.
2017.07.27 07:00:59 3: WARNING Wifilight4_Timeout error!
Bis jetzt (19:32 Uhr) keine weiteren Meldungen vom device!?
Nach reboot de Raspi:
2017.07.27 19:37:13 5: PRESENCE (Wifilight4) - starting ping scan: Wifilight4|192.168.2.106|0|4
2017.07.27 19:37:14 2: sduino3: initialized. v3.3.1-dev
2017.07.27 19:37:14 3: sduino3/init: enable receiver (XE)
2017.07.27 19:37:20 5: PRESENCE (Wifilight4) - ping command returned with output:
PING 192.168.2.106 (192.168.2.106) 56(84) bytes of data.
From 192.168.2.140 icmp_seq=1 Destination Host Unreachable
From 192.168.2.140 icmp_seq=2 Destination Host Unreachable
From 192.168.2.140 icmp_seq=3 Destination Host Unreachable
From 192.168.2.140 icmp_seq=4 Destination Host Unreachable
--- 192.168.2.106 ping statistics ---
4 packets transmitted, 0 received, +4 errors, 100% packet loss, time 3101ms
pipe 4
Bis 19:49 Uhr keine weiteren Meldungen im Log. Aber Statuscheck sagt:
another check is currently running
list auf device:
Internals:
ADDRESS 192.168.2.106
CFGFN
DEF lan-ping 192.168.2.106 60 300
MODE lan-ping
NAME Wifilight4
NOTIFYDEV global
NR 734
NTFY_ORDER 50-Wifilight4
STATE present
TIMEOUT_NORMAL 60
TIMEOUT_PRESENT 300
TYPE PRESENCE
READINGS:
[color=red] 2017-07-27 19:35:04 model lan-ping
2017-07-26 21:11:21 presence absent
2017-07-26 22:57:33 state present [/color]
helper:
ABSENT_COUNT 4
PRESENT_COUNT 0
RUNNING_PID:
abortFn PRESENCE_ProcessAbortedScan
arg Wifilight4|192.168.2.106|0|4
bc_pid 19
finishFn PRESENCE_ProcessLocalScan
fn PRESENCE_DoLocalPingScan
pid DEAD:1698
timeout 60
abortArg:
Attributes:
absenceThreshold 5
event-on-change-reading state
room LED
verbose 5
Ich verstehs nicht :(
mit dem Problem bist du nicht allein.
Bei mir fällt es bei zwei Geräten besonders häufig auf.
mein workaround: ich editiere das Device und speichere neu ab. meistens reicht das schon.
Was mich vermuten lässt, das es kein "Hardware"-Problem vom Rechner aus gibt, sondern sich FHEM bzw das Modul irgendwo verschluckt
ich hatte bislang nur keine Zeit, dem weiter auf den Grund zu gehen.
hab jetzt mal die beiden Device auf verbose 5 gesetzt, vielleicht ergibt sich da was .
vb
Gut zu wissen dass ich mit dem Problem nicht ganz alleine bin :)
Was ich in den letzten Tagen so rausgefunden habe ist nicht viel. Irgendwann stellt lan-ping einfach die Arbeit ein... >:( Da hilft kein verbose=5, nur (manchmal) ein reboot.
sind wohl doch nur 2 Leute betroffen >:(
Hallo
Ich habe vor mit vor einer Woche das presence mit checkFritzMACpresent wie im Wiki beschrieben eingerichtet.
Leider ist es praktisch nicht benutzbar, denn der Test bleibt alle paar Stunden sporadisch hängen.
Auf eine manuelle Abfrage kommt dann "another check is currently running".
Wenn ich dann auf "DEF" zum editieren klicke und dann (ohne etwas zu ändern) auf "modify ..." wird der Check sofort ausgeführt und läuft dann wieder eine variable Zeit.
73 de Ronald
Zitat von: VB90 am 29 Juli 2017, 09:14:39
mit dem Problem bist du nicht allein.
Bei mir fällt es bei zwei Geräten besonders häufig auf.
mein workaround: ich editiere das Device und speichere neu ab. meistens reicht das schon.
Was mich vermuten lässt, das es kein "Hardware"-Problem vom Rechner aus gibt, sondern sich FHEM bzw das Modul irgendwo verschluckt
ich hatte bislang nur keine Zeit, dem weiter auf den Grund zu gehen.
hab jetzt mal die beiden Device auf verbose 5 gesetzt, vielleicht ergibt sich da was .
vb
Ganz genau so ist es bei mir auch.
Grtz
Da dieser Fall mir bisher nur in Verbindung mit dem Wikibeispiel checkFritzMACpresent auftritt, gehe ich davon aus, dass bei der Ausführung von der Funktion ein Perl-Syntax-Fehler oder anderweitiger Perl-Fehler auftritt, der zum Beenden des Perl-Interpreters führt und dadurch keinerlei Rückmeldung/Logmeldung zu erkennen ist. Anders kann ich mir das Phänomen nicht erklären.
Was kommt, wenn ihr den Funktionsaufruf mal manuell direkt in der FHEMWEB Befehlszeile eingebt?
Gruß
Markus
Hallo Markus
Wenn man auf einen sporadischen Fehler wartet dauerts etwas länger ...
Gestern hat die Funktion den ganzen Tag durchgehalten, heute früh um 4:43 hat sich aber wieder eine meiner 2 Abfragen aufgehängt.
Die Andere lief weiter.
2017-08-23_04:22:48 Pres_Ron presence: present
2017-08-23_04:27:06 Pres_Steffi presence: absent
2017-08-23_04:32:55 Pres_Ron presence: present
2017-08-23_04:37:47 Pres_Steffi presence: absent
2017-08-23_04:43:04 Pres_Ron presence: present
2017-08-23_04:48:20 Pres_Steffi presence: absent
2017-08-23_04:59:20 Pres_Steffi presence: absent
2017-08-23_05:09:57 Pres_Steffi presence: absent
2017-08-23_05:20:34 Pres_Steffi presence: absent
2017-08-23_05:31:09 Pres_Steffi presence: absent
Wenn ich die Funktion im Browser in der FHEM-Eingabezeile oder in der Telnet-Konsole eingebe funktioniert es ohne Probleme :
{checkFritzMACpresent("Fritzbox","D0:87:E2:33:BE:9E")} liefert 0 oder 1.
Woran erkennt FHEM das "another check is currently running" ? Wird das ev. nicht zuverlässig gelöscht ?
Was passiert wenn man die Modify-Funktion benutzt? Denn dann geht es ja sofort wieder.
Wird hier dann der interne Merker gelöscht ?
Würde ein Timeout-Mechanismus für den Merker helfen ?
Gruß Ronald
Ich habe dieses Problemchen auch. Und zwar sporadisch nach einem update/restart.
Zitatmein workaround: ich editiere das Device und speichere neu ab. meistens reicht das schon.
So bekomme ich die devices auch wieder ins Lot. Bei mehreren devices ist das aber sehr lästig...
Mit meinem update/restart-Thema habe ich mir so geholfen:
global:INITIALIZED {
fhem "sleep 5; defmod PhilipsTV.PRE PRESENCE lan-ping 10.x.y.z 60 60";
fhem "sleep 10; defmod ReadyNAS.PRE PRESENCE lan-ping 10.x.y.z 60 60";
}Die devices nehmen ihren tatsächlichen status ein und "another check is currently running" tritt nicht mehr auf.
VG Sebastian
Hallo Ronald,
Zitat von: sky64 am 23 August 2017, 10:42:52
Woran erkennt FHEM das "another check is currently running" ?
Wenn man ein "list <NAME>" von der entsprechenden PRESENCE-Definition ausführt, sieht man, dass es unter Internals->Helper ein Element "RUNNING_PID" mit weiterführenden Informationen zu dem geforkten Prozess in dem der Check ausgeführt wird (via Hilfsmodul Blocking.pm). Dieser Unterprozess meldet dann ein erfolgreiches Ausführen des Checks (unabhängig was für ein Anwesenheitsergebnis) durch Aufruf von der Funktion PRESENCE_ProcessLocalScan() an die jeweilige Definition zurück. Sollte der Unterprozess den maximalen Timeout überschreiten (60 Sekunden) wird dies von dem Unterprozess durch den Aufruf der Funktion PRESENCE_ProcessAbortedScan() ebenfalls zurückgemeldet. Dieses Verhalten gilt allgemein für alle Module die solche entkoppelten Aufrufe via Blocking.pm durchführen.
Bei jedem geplanten oder manuellen Start eines Checks wird geprüft, ob RUNNING_PID existiert, woraus PRESENCE den Schluss zieht, es läuft gerade ein Check. Da es keine andere Möglichkeit gibt, zu prüfen
Zitat von: sky64 am 23 August 2017, 10:42:52
Wird das ev. nicht zuverlässig gelöscht ?
Beide Funktionen löschen bei Aufruf dann den Eintrag unter RUNNING_PID und beenden damit den Scan. Da beide Funktionen NICHT aufgerufen werden und auch sonst keinerlei Logmeldungen zu sehen sind, gehe ich davon aus, dass der Unterprozess garnicht erst gestartet wird, oder bei der Ausführung des jeweiligen Scans in einen groben Fehler reinläuft, der den Prozess sofort beenden lässt.
Das Modul Blocking.pm prüft systemweit alle Unterprozesse, ob sie noch laufen durch eine Art Ping an den Unterprozess. In den "list"-Ausgaben von arthur_dent_2015 kann man bspw. erkennen, dass unter "RUNNING_PID" das Element "pid" mit "DEAD" angegeben ist. Dies passiert, sollte ein Unterprozess nicht mehr auf diesen Ping reagieren. Warum der Prozess jedoch vorzeitig gestorben ist, kann man nicht erkennen, da es offenbar keine Logmeldungen gibt.
Zitat von: sky64 am 23 August 2017, 10:42:52
Was passiert wenn man die Modify-Funktion benutzt? Denn dann geht es ja sofort wieder. Wird hier dann der interne Merker gelöscht ?
Das liegt daran, dass bei einem Define das Internal unter Helper->RUNNING_PID immer gelöscht wird um mit einem definierten Stand anzufangen, sollte durch Änderungen wie Umbenennen sich der Name während eines laufenden Checks ändern. Dies würde auch zu einem solchen Ergebnis führen.
Zitat von: sky64 am 23 August 2017, 10:42:52
Würde ein Timeout-Mechanismus für den Merker helfen ?
Hierzu muss ich mal Rudi kontaktieren (Maintainer von Blocking.pm). Ich werde mal in FHEM-Development einen Thread dazu eröffnen.
Viele Grüße
Markus
Hallo Markus
vielen Dank für die Erklärungen.
Ich habe z.Z. den Eindruck das es aktuell seltener zu dem Hänger kommt. Warum ... unklar.
Wie es aussieht scheint es aber ein generelles Problem zu sein, denn ich nutze "funktion" und z.B. Sebastian nutzt "lan-ping".
Gruß Ronald
PRESENCE-Devices benutze ich schon länger (LAN-Ping und function) und kannte diese Probleme bis vor kurzem nicht. Seit einiger Zeit habe ich zusätzlich Bluetooth-Devices mit reingenommen (zur Konfiguration: Ich benutze einen collectord, der sich an einen presenced und einen lepresenced verbindet, beide auf den gleichen Adapter - soll aber eigentlich möglich sein).
Naja, seitdem habe ich alle paar Tage Probleme mit einem aufgefressenen Arbeitsspeicher durch den presenced, den ich bisher auch beschuldigt habe. Der presenced wächst innerhalb einiger Tage auf ~400M, bis das Problem sich bemerkbar macht. Die Symptome zu dem Zeitpunkt ähneln den hier beschriebenen ("another check is currently running" .. "kann nicht fork()en, kein freier Speicher"). Interessanterweise hilft durchstarten des presenced zwar dem RAM, aber nicht den betroffenen PRESENCE-Devices - die bleiben in einem undefinierten Zustand hängen, bis ich FHEM durchstarte.
Nachdem ich den Thread hier gelesen habe, frage ich mich, ob der presenced da überhaupt Schuld hat oder ob er durch irgendein Verhalten des PRESENCE-Moduls an eine Grenze gebracht wird.
Dieses Problem mit ansteigendem Speicherverbrauch von presenced habe ich ebenfalls schonmal gehört. Kann ich bei mir aber nicht nachstellen. Ich habe eine durchgängig laufende Installation von presenced auf einem Raspi zusammen mit einem collectord und der Speicherverbrauch ist konstant niedrig bei 0,8%. Der collectord hat 1,1%.
Gruß
Markus
Moin Markus,
im FHEM Log gibt es, auch bei verbose 5, keine Einträge. Mein Fhem läuft auf einem Raspi 3 mit aktuellem Jessie.
Im Moment nutze in Nmap für absent/present. Das ist aber auch nicht soooo zuverlässig :( Wenn ich ein über WLAN angebundenes device schalten will möchte ich schon sicher sein dass das Gerät zu dem Zeitpunkt auch erreichbar ist.
Gibt es eine Möglichkeit dem Problem auf die Spur zu kommen? Es muss ja einen Grund für das vorzeitige Ableben des Prozesses geben...
Gruß
Arthur
Hallo Markus,
seit zwei Tagen wurde der Status zwei meiner Geräte in FHEM nicht mehr aktualisiert, die auf die gleiche IP Adresse zielen.
defmod LGwebOSTV PRESENCE lan-ping 192.168.178.70 10 30
defmod LG_WOL WOL 3C:CD:93:99:10:33 192.168.178.70 UDP
Alle anderen PRESENCE und WOL Geräte funktionieren. Ähnliche Definitionen auf anderen FHEM Instanzen (Ziel ist die gleiche IP) funktionierten auch durchgängig.
Ein einfaches defmod ... (also einfache execute in der Raw Def) hat das Problem soeben behoben.
Hat das eventuell etwas mit deiner momentanen "Problem Forschung" zu tun? Kann ich da irgendetwas dazu beitragen? Ist allerdings hier bisher nur einmal aufgetreten.
Gruß Otto
Hi,
hatte früher ebenfalls die Problematik, als ich über lan-ping ca. 15 Devices überwacht habe.
Inzwischen habe ich es auf 7 reduziert und es verhält sich so, wie es soll.
Der RAM war nie das Problem, sondern wohl eher, dass sich irgendwas "verharkt" hatte.
Gruß
Danny