Blocking HTTP/API-request durch Winterzeit oder was brachte mich um den Schlaf ?

[KölnSolar]

Die Cloud, die Cloud, die tolle Cloud(Ironie aus)

... hat mir vermutlich heute Nacht den Schlaf geraubt. Und das, wo ich sooo ein Freund der Cloud bin, aber das ist ein anderes Thema.

Mein check_jammer schlug ab 2 Uhr(was mir natürlich anfänglich nicht auffiel)  alle 5 min.(was mir ebenfalls anfänglich nicht auffiel) Alarm. Ich suchte, suchte, suchte nach dem Grund der Auslösung. Nachdem die aufgeweckten Mitbewohner wieder in Tiefschlaf verfallen waren(nach 3) guckte ich konzentrierter ins Log, in den event monitor...alles bestens. Komisch. Also den disabelten check-jammer wieder aktiviert. Und ? Alles ruhig 

Im nachhinein betrachtet muss es mit der Zeitumstellung zusammenhängen u., da ich keine eigenen periodischen Abfragen mit 5 min. Zyklus habe, ein Zugriff auf die "Cloud". Bei den meisten(wenigen) habe ich eigene(ungleich 5 min.) Intervalle definiert, die ich also ausschließen kann. Übrig bleiben: fitbit(Standardintervall 5min. !!!), airquality(developmentstatus), amazonecho(developmentstatus), alexa(die macht aber doch zyklisch nichts und der echo ist bei mir nachts eh aus).

Aus dem Log ist rein gar nichts ersichtlich, außer dass es beim 2. 2-3Uhr stattfand.

Hat jemand ähnliches bei sich beobachtet ?

Was kann da technisch hinter stecken ? Ein nicht erreichbarer, weil für das 2. 2-3Uhr abgeschalteter, Cloud-Server ? Das blocking/non-blocking Thema, was ich immer wieder irgendwo lese ohne es detailliert zu verstehen ? Kann der Modulauthor das verhindern(würde ja dann auch passieren, wenn der Server aus anderen Gründen down ist) ?

schlaflose Grüße
Markus

[viegener]

Ich kenne Deinen check_jammer nicht genau, ich habe im Forum nur den status-check für TRXUSB von Dir gefunden?

Mit ist aber nicht klar, was der jetzt mit Cloud-Diensten zu tun hat?

Aber auch bei mir gab es diese Nacht ein paar komische Effekte:
- HM ActionDetector hat alles erst dead dann alive gemeldet
- Sonos ist auch etwas durcheinandergekommen

Mein Vorteil ist nur die Meldungen sind bei mir auf telegram aufgelaufen und ich habe erst heute morgen analysiert

[MadMax-FHEM]

Selbes bei mir...

ActionDetector aber auch "nur" per Telegram...
...Handy hat halt geblinkt...

Gruß, Joachim

[KölnSolar]

Danke Euch.

status-check für TRXUSB von Dir gefunden?

Genau der 

Nur der TRX lief brav(keine disconnects oder ähnlich), die Sensoren funkten.... Aber alle 5 min. Alarm. Und dann habe ich halt geguckt, was denn so alle 5min. läuft und möglicherweise den Empfang vom TRX blockiert/verzögert. Keine at's, keine Sensoren, z.B. weather nur alle 30' und übrig blieb o.g.

Mein Vorteil ist nur die Meldungen sind bei mir auf telegram aufgelaufen und ich habe erst heute morgen analysiert

Wenn ich etwas Positives für meine Situation sehen will: Ich bin wenigstens nicht bei Sturm u. Regen vor die Tür gerannt und hab den bösen Jammer gesucht 

Edit: HM hab ich nicht.

[viegener]

ich habe mir den check_jammer nochmal angeschaut und es könnte sein, dass es wirklich ein grundsätzliches problem gibt.

Also durch die zeitumstellung gibt es ja die Zeiten zwischen 2 und 3 Uhr heute doppelt. Jetzt wird bei ReadingAge aber ein Textzeitpunkt in eine Anzahl Sekunden der Epoche umegwandelt - Frage in welche (laut utils eigentlich in den späteren - mktime...dst = -1)

Wenn der Readingszeitpunkt in den frühen Zeitpunkt umgewandelt wird so ist natürlich die aktuelle Zeit nach der Zeitumstellung immer mindestens 60min später also schlägt der Jammer das erste mal vermutlich um 5 nach 2 nach der Zeitumstellung zu.

Also noch keine Erklärung für mich. Spontan fällt mir aber am Sonntag auch nicht ein, wie man das lösen könnte ohne die Information über mit Sommerzeit oder ohne SZ an den Zeitstempel jeweils mitzuschleifen (oder gar ein ISO-Zeitstempel daraus zu machen)

[KölnSolar]

Oha und ich hab andere der Schuld bezichtigt 

Drüber nachgedacht hatte ich heute Nacht auch schon. Hab mir dann den Timestamp angeguckt und ReadingsAge vor Augen geführt. Macht ja nix anderes als Differenz der aktuellen Uhrzeit zum Timestamp zurückzugeben. Aber das war, bevor ich auf die Idee kam, dass es an der Zeitumstellung liegen muss.

Ha, da hattest Du mich fast überzeugt, dass es am ReadingsAge liegt und wollte schon ein gelöst posten, aber

in der laufenden Fassung frage ich alle 5 Sekunden ab, ob die Differenz > 40 sec. ist. Folglich hatte der Jammer permanent alarmieren müssen und nicht nur alle 5 min.

Muss Dir also spontan am Sonntag nix mehr zu einfallen 

[viegener]

Ich konnte bisher auch das ReadingsAge nicht bezichtigen, es ist nur klar, dass es irgendwie mit der Zeitumstellung zusammenhängt und offensichtlich die Zeiten zwischen 2 und 3 nicht eindeutig sind. Es kann aber sicher auch ausserhalb von FHEM liegen.

Vielleicht postest Du mal den Code, der die Meldungen ausgelöst hat?

[KölnSolar]

da iss nicht mehr als ich schon beschrieben hab

Code Auswählen Erweitern

define check_jammer at +*00:00:05 {if (ReadingsAge('TRXUSB','state',0) > 40) {Voicecmd('jammer')}}

sub Voicecmd() ist in der myUtils und gibt auf einem FS20-SIG2 und meinem echo dot jeweils eine mp3-Nachricht in Abhängigkeit des übergebenen Parameters aus.

[viegener]

Hat sich denn der state in der Zeit verändert (hast Du dazu einen log oder ist das per event-on/etc abgeklemmt)?

[viegener]

Kannst Du mal ein list von dem TRX-Device machen?

[KölnSolar]

State hat sich in den 5-minütigen Alarm-Pausen verändert. Das hatte mich ja so verwirrt. Und im event monitor fällt einem die Zeitdifferenz nicht auf. Log gibt es keins 

Im List siehst Du eigentlich nur, dass er nie disconnected war, was auch dmesg bestätigte: kein Eintrag

Code Auswählen Erweitern

Internals:
   DEF        /dev/serial/by-id/usb-RFXCOM_RFXtrx433_02VEJQFT-if00-port0@38400
   DeviceName /dev/serial/by-id/usb-RFXCOM_RFXtrx433_02VEJQFT-if00-port0@38400
   FD         60
   NAME       TRXUSB
   NR         84
   PARTIAL
   RAWMSG     0a520164680200c8380179
   STATE      Initialized
   TRXUSB_MSGCNT 123184
   TRXUSB_TIME 2017-10-29 12:07:20
   TYPE       TRX
   READINGS:
     2017-10-29 12:07:20   state           Initialized
Attributes:
   longids    THGR228N
   room       System

[viegener]

Mmmmh - da ist kein minintervall doer ähnliches

Und Du bist sicher, dass das Problem NACH der Zeitumstellung auftrat?

Dann fehlt mir gerade eine passende Erklärung, denn die Zeitstempel an den Readings werden eigentlich immer ohne DST umgewandelt

[KölnSolar]

Du glaubst mir aber auch nix  Aber ich kenn ja die Situation, wenn man es selber nicht vor Augen hat.

Code Auswählen Erweitern

2017.10.29 02:11:38 2: Skipping missing readings before 2017-10-28 02:11:38
bis hier muss also das erste mal 2-3 Uhr gelaufen sein

und dann das 2. Mal mit dem Alarm
2017.10.29 02:04:27 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:32 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:37 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:42 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:42 3: CULFB: Unknown code ? ( is unknown) Use one of A B C E e F G h i K k l M m N R T t U u V W X x Y y Z, help me!
2017.10.29 02:04:47 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:52 3: FS20 set Sig1111 dim93%
2017.10.29 02:04:57 3: FS20 set Sig1111 dim93%
2017.10.29 02:11:38 2: Skipping missing readings before 2017-10-28 03:11:38
2017.10.29 02:11:38 2: Skipping missing readings before 2017-10-28 03:11:38
2017.10.29 02:11:38 2: Received 0 values for radiation
2017.10.29 02:11:38 2: Skipping missing readings before 2017-10-28 03:11:38
2017.10.29 02:11:38 2: Skipping missing readings before 2017-10-28 03:11:38
2017.10.29 02:14:27 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:32 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:37 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:42 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:47 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:52 3: FS20 set Sig1111 dim93%
2017.10.29 02:14:57 3: FS20 set Sig1111 dim93%
2017.10.29 02:34:27 3: FS20 set Sig1111 dim93%
.
.
.


Ich bleib erst einmal dabei: irgendetwas hat FHEM blockiert, meine 40sec.(hab ich am Anfang auch noch etwas höher gesetzt) wurden überschritten und dann der Alarm und irgendwann war die Blockade wieder weg, bis sie 5min. später wieder auftrat. Und das alles nur von 2-3(was ich übrigens erst später bemerkte, da ich den SIG2 ausgestöpselt hatte)

[viegener]

Mmmh - überzeugt - das ist die zweiter Runde von 2-3...

Ob da etwas 40 Sekunden blockiert kann ich erlich gesagt nicht sagen und kommt mir auch komisch vor, wenn Du später die events hast reinkommen sehen im eventviewer?

Also vielleicht einfach ein at definieren, der den check_jammer am Ende der SOmmerzeit für 2 h ausschaltet

[KölnSolar]

Also vielleicht einfach ein at definieren, der den check_jammer am Ende der SOmmerzeit für 2 h ausschaltet

Klar. Wird aber vermutlich noch einfacher. Abschaffung der Sommerzeit 

Aber damit ist es ja nicht wirklich aus der Welt, denn ich spekuliere ja, dass es ein "server down" eines Webservers war, den ich mit dem mir unbekannten Modul abfragte.  Und das kann ja immer mal passieren

Danke für Deine Geduld.