PRESENCE: another check is currently running [update]

[arthur_dent_2015]

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:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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

[arthur_dent_2015]

Bin ich wirklich der Einzige mit diesem Problem?

[Markus Bloch]

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

[arthur_dent_2015]

Hallo Markus,
das Problem habe ich ständig, meist die selben devices. Z.B.

Code Auswählen Erweitern


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.

Code Auswählen Erweitern


MemTotal:         994232 kB
MemFree:          393108 kB
MemAvailable:     617376 kB

Ich hab jetzt mal ein device auf verbose=5 gesetzt und werde beobachten.
Gruß
Arthur

[arthur_dent_2015]

z.B. gestern Abend:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


2017.07.26 21:35:26 3: WARNING Wifilight4_Timeout error!

dann ist Ruhe.... bis

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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.

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


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:

Code Auswählen Erweitern


another check is currently running

list auf device:

Code Auswählen Erweitern


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 

[VB90]

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

[arthur_dent_2015]

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.

[arthur_dent_2015]

sind wohl doch nur 2 Leute betroffen 

[sky64]

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

[C0mmanda]

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

[Markus Bloch]

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

[sky64]

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.

Code Auswählen Erweitern


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 :

Code Auswählen Erweitern

{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

[binford6000]

Ich habe dieses Problemchen auch. Und zwar sporadisch nach einem update/restart.

mein 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:

Code Auswählen Erweitern

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

[Markus Bloch]

Hallo Ronald,

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

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.

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.

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

[sky64]

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