Hallo zusammen,
bei mir läuft seit einiger Zeit DoorPi 2.5.1 auf einem Raspi 3 (Jessie) im Probebetrieb. Gestern habe ich testweise meinen Bewegungsmelder in Betrieb genommen. Es handelt sich um diesen Bewegungsmelder, der i.W. wie hier vorgeschlagen an den PiFace Digital 2, Eingang #2 angeschlossen ist. Die Hardware habe ich vorab in ausgebautem Zustand getestet und ich habe hinter dem MOSFET (Q2 im Schaltplan von PAH) ein zuverlässiges Signal erhalten, welches sich wie erwartet Verhalten hat.
Für den Testbetrieb wollte ich erstmal nur das Auslösen des PiFace Eingangs protokollieren. Hierzu habe ich die folgende Konfiguration in der doorpi.ini gemacht (Auszug, entscheidend sind Zeile 6-7)
[...]
[EVENT_OnKeyPressed_piface.1]
10 = os_execute:doorpi-tools.sh log "Eingang 1 (LIT) wurde ausgelöst"
[EVENT_OnKeyPressed_piface.2]
10 = os_execute:doorpi-tools.sh log "Eingang 2 (MOV) wurde ausgelöst"
[EVENT_OnKeyDown_piface.3]
10 = os_execute:doorpi-tools.sh log "Übergang 0->1 an Eingang 3 (BRI) detektiert"
[EVENT_OnKeyUp_piface.3]
10 = os_execute:doorpi-tools.sh log "Übergang 1->0 an Eingang 3 (BRI) detektiert"
[EVENT_OnKeyPressed_piface.4]
10 = os_execute:doorpi-tools.sh log "Eingang 4 (SABI) wurde ausgelöst"
[...]
Alles anzeigen
Anmerkung: Da ich mit dem log-Befehl von DoorPi nicht zurechtgekommen bin (dieser scheint nur im trace-Modus des doorpi client zu protokollieren), verwende ich ein Shell-Skript, um die Nachrichten in das Protokoll zu schreiben.
Das Mysteriöse ist nun, dass der Eingang 2 (bzw. das Event für Eingang 2) seit Testbeginn (gestern gegen 11:30) zuverlässig alle 30 Minuten ausgelöst hat. Das sieht dann im Protokoll doorpi.log so aus
[...]
2017-10-08 15:09:02,092 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 15:39:01,487 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 15:53:28,562 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 15:55:05,322 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 15:57:17,776 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 16:09:01,786 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 16:39:02,173 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 17:09:01,491 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 17:39:01,817 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 18:09:02,094 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 18:39:01,494 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 19:09:01,794 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 19:39:02,211 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 20:09:01,444 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 20:39:01,834 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 21:09:02,094 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 21:17:46,840 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 21:36:53,690 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
2017-10-08 21:39:01,474 [INFO] [] Eingang 2 (MOV) wurde ausgelöst
Alles anzeigen
Ein Schaltungsproblem kann ich fast sicher ausschließen, denn dadurch ist ein solch präzises Auslösen alle 30 Minuten über mehr als einen Tag hinweg kaum erklärbar (und ab und zu gibt es auch "echte" Auslösungen wie z.B. um 21:36:53). Daher vermute ich eher, dass das Problem durch den Raspi (bzw. dessen Software) erzeugt wird.
Ein Blick in /var/log/syslog offenbart Verdächtiges
Oct 8 15:09:01 sprechstelle CRON[29965]: (root) CMD ( [ -x /usr/lib/php5/sessi
onclean ] && /usr/lib/php5/sessionclean)
Oct 8 15:17:01 sprechstelle CRON[31868]: (root) CMD ( cd / && run-parts --rep
ort /etc/cron.hourly)
Oct 8 15:39:01 sprechstelle CRON[4561]: (root) CMD ( [ -x /usr/lib/php5/sessio
nclean ] && /usr/lib/php5/sessionclean)
Oct 8 16:09:01 sprechstelle CRON[11616]: (root) CMD ( [ -x /usr/lib/php5/sessi
onclean ] && /usr/lib/php5/sessionclean)
Oct 8 16:17:01 sprechstelle CRON[13524]: (root) CMD ( cd / && run-parts --rep
ort /etc/cron.hourly)
Oct 8 16:39:01 sprechstelle CRON[18633]: (root) CMD ( [ -x /usr/lib/php5/sessi
onclean ] && /usr/lib/php5/sessionclean)
Oct 8 17:09:01 sprechstelle CRON[25644]: (root) CMD ( [ -x /usr/lib/php5/sessi
onclean ] && /usr/lib/php5/sessionclean)
Oct 8 17:17:01 sprechstelle CRON[27553]: (root) CMD ( cd / && run-parts --rep
ort /etc/cron.hourly)
Oct 8 17:39:01 sprechstelle CRON[32659]: (root) CMD ( [ -x /usr/lib/php5/sessi
onclean ] && /usr/lib/php5/sessionclean)
Oct 8 18:09:01 sprechstelle CRON[7261]: (root) CMD ( [ -x /usr/lib/php5/sessionclean ] && /usr/lib/php5/sessionclean)
Alles anzeigen
Jeweils um :09 und :39 läuft offenbar ein Cronjob. Ich vermute hier einen Zusammenhang, kann mir aber z.B. nicht erklären, warum dieser Cronjob zu einem solchen Seiteneffekt führen sollte und weshalb z.B. nur Eingang #2 betroffen ist. Für die anderen Eingänge sind ebenfalls Events auf die gleiche Art und Weise registriert und diese werden auf die gleiche Art und Weise protokolliert. Hier beobachte ich jedoch keinerlei falsche Auslösungen (an Eingang 0 hängt z.B. die Klingel, die ebenfalls über OnKeyPressed abgefragt wird - bisher hat es noch nie einfach so geklingelt ).
Hat irgendjemand eine Erklärung für dieses Verhalten (und wie ich dieses Verhalten unterbinden kann)?
Viele Grüße,
Thomas